LogStatistics.cpp revision 4ba0387af5acc52e43e4004ccb4c46b8bc700349
1/* 2 * Copyright (C) 2014 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17#include <fcntl.h> 18#include <stdarg.h> 19#include <time.h> 20 21#include <log/logger.h> 22#include <private/android_filesystem_config.h> 23#include <utils/String8.h> 24 25#include "LogStatistics.h" 26 27PidStatistics::PidStatistics(pid_t pid, char *name) 28 : pid(pid) 29 , mSizesTotal(0) 30 , mElementsTotal(0) 31 , mSizes(0) 32 , mElements(0) 33 , name(name) 34{ } 35 36#ifdef DO_NOT_ERROR_IF_PIDSTATISTICS_USES_A_COPY_CONSTRUCTOR 37PidStatistics::PidStatistics(const PidStatistics ©) 38 : pid(copy->pid) 39 , name(copy->name ? strdup(copy->name) : NULL) 40 , mSizesTotal(copy->mSizesTotal) 41 , mElementsTotal(copy->mElementsTotal) 42 , mSizes(copy->mSizes) 43 , mElements(copy->mElements) 44{ } 45#endif 46 47PidStatistics::~PidStatistics() { 48 free(name); 49} 50 51void PidStatistics::setName(char *new_name) { 52 free(name); 53 name = new_name; 54} 55 56void PidStatistics::add(unsigned short size) { 57 mSizesTotal += size; 58 ++mElementsTotal; 59 mSizes += size; 60 ++mElements; 61} 62 63bool PidStatistics::subtract(unsigned short size) { 64 mSizes -= size; 65 --mElements; 66 return mElements == 0 && kill(pid, 0); 67} 68 69void PidStatistics::addTotal(size_t size, size_t element) { 70 if (pid == gone) { 71 mSizesTotal += size; 72 mElementsTotal += element; 73 } 74} 75 76// must call free to release return value 77char *PidStatistics::pidToName(pid_t pid) { 78 char *retval = NULL; 79 if (pid != PidStatistics::gone) { 80 char buffer[512]; 81 snprintf(buffer, sizeof(buffer), "/proc/%u/cmdline", pid); 82 int fd = open(buffer, O_RDONLY); 83 if (fd >= 0) { 84 ssize_t ret = read(fd, buffer, sizeof(buffer)); 85 if (ret > 0) { 86 buffer[sizeof(buffer)-1] = '\0'; 87 // frameworks intermediate state 88 if (strcmp(buffer, "<pre-initialized>")) { 89 retval = strdup(buffer); 90 } 91 } 92 close(fd); 93 } 94 } 95 return retval; 96} 97 98UidStatistics::UidStatistics(uid_t uid) 99 : uid(uid) { 100 Pids.clear(); 101} 102 103UidStatistics::~UidStatistics() { 104 PidStatisticsCollection::iterator it; 105 for (it = begin(); it != end();) { 106 delete (*it); 107 it = Pids.erase(it); 108 } 109} 110 111void UidStatistics::add(unsigned short size, pid_t pid) { 112 PidStatistics *p; 113 PidStatisticsCollection::iterator last; 114 PidStatisticsCollection::iterator it; 115 for (last = it = begin(); it != end(); last = it, ++it) { 116 p = *it; 117 if (pid == p->getPid()) { 118 p->add(size); 119 // poor-man sort, bubble upwards if bigger than last 120 if ((last != it) && ((*last)->sizesTotal() < p->sizesTotal())) { 121 Pids.erase(it); 122 Pids.insert(last, p); 123 } 124 return; 125 } 126 } 127 // poor-man sort, insert if bigger than last or last is the gone entry. 128 bool insert = (last != it) 129 && ((p->getPid() == p->gone) 130 || ((*last)->sizesTotal() < (size_t) size)); 131 p = new PidStatistics(pid, pidToName(pid)); 132 if (insert) { 133 Pids.insert(last, p); 134 } else { 135 Pids.push_back(p); 136 } 137 p->add(size); 138} 139 140void UidStatistics::subtract(unsigned short size, pid_t pid) { 141 PidStatisticsCollection::iterator it; 142 for (it = begin(); it != end(); ++it) { 143 PidStatistics *p = *it; 144 if (pid == p->getPid()) { 145 if (p->subtract(size)) { 146 size_t szsTotal = p->sizesTotal(); 147 size_t elsTotal = p->elementsTotal(); 148 delete p; 149 Pids.erase(it); 150 it = end(); 151 --it; 152 if (it == end()) { 153 p = new PidStatistics(p->gone); 154 Pids.push_back(p); 155 } else { 156 p = *it; 157 if (p->getPid() != p->gone) { 158 p = new PidStatistics(p->gone); 159 Pids.push_back(p); 160 } 161 } 162 p->addTotal(szsTotal, elsTotal); 163 } 164 return; 165 } 166 } 167} 168 169size_t UidStatistics::sizes(pid_t pid) { 170 size_t sizes = 0; 171 PidStatisticsCollection::iterator it; 172 for (it = begin(); it != end(); ++it) { 173 PidStatistics *p = *it; 174 if ((pid == pid_all) || (pid == p->getPid())) { 175 sizes += p->sizes(); 176 } 177 } 178 return sizes; 179} 180 181size_t UidStatistics::elements(pid_t pid) { 182 size_t elements = 0; 183 PidStatisticsCollection::iterator it; 184 for (it = begin(); it != end(); ++it) { 185 PidStatistics *p = *it; 186 if ((pid == pid_all) || (pid == p->getPid())) { 187 elements += p->elements(); 188 } 189 } 190 return elements; 191} 192 193size_t UidStatistics::sizesTotal(pid_t pid) { 194 size_t sizes = 0; 195 PidStatisticsCollection::iterator it; 196 for (it = begin(); it != end(); ++it) { 197 PidStatistics *p = *it; 198 if ((pid == pid_all) || (pid == p->getPid())) { 199 sizes += p->sizesTotal(); 200 } 201 } 202 return sizes; 203} 204 205size_t UidStatistics::elementsTotal(pid_t pid) { 206 size_t elements = 0; 207 PidStatisticsCollection::iterator it; 208 for (it = begin(); it != end(); ++it) { 209 PidStatistics *p = *it; 210 if ((pid == pid_all) || (pid == p->getPid())) { 211 elements += p->elementsTotal(); 212 } 213 } 214 return elements; 215} 216 217LidStatistics::LidStatistics() { 218 Uids.clear(); 219} 220 221LidStatistics::~LidStatistics() { 222 UidStatisticsCollection::iterator it; 223 for (it = begin(); it != end();) { 224 delete (*it); 225 it = Uids.erase(it); 226 } 227} 228 229void LidStatistics::add(unsigned short size, uid_t uid, pid_t pid) { 230 UidStatistics *u; 231 UidStatisticsCollection::iterator it; 232 UidStatisticsCollection::iterator last; 233 234 if (uid == (uid_t) -1) { // init 235 uid = (uid_t) AID_ROOT; 236 } 237 238 for (last = it = begin(); it != end(); last = it, ++it) { 239 u = *it; 240 if (uid == u->getUid()) { 241 u->add(size, pid); 242 if ((last != it) && ((*last)->sizesTotal() < u->sizesTotal())) { 243 Uids.erase(it); 244 Uids.insert(last, u); 245 } 246 return; 247 } 248 } 249 u = new UidStatistics(uid); 250 if ((last != it) && ((*last)->sizesTotal() < (size_t) size)) { 251 Uids.insert(last, u); 252 } else { 253 Uids.push_back(u); 254 } 255 u->add(size, pid); 256} 257 258void LidStatistics::subtract(unsigned short size, uid_t uid, pid_t pid) { 259 UidStatisticsCollection::iterator it; 260 for (it = begin(); it != end(); ++it) { 261 UidStatistics *u = *it; 262 if (uid == u->getUid()) { 263 u->subtract(size, pid); 264 return; 265 } 266 } 267} 268 269size_t LidStatistics::sizes(uid_t uid, pid_t pid) { 270 size_t sizes = 0; 271 UidStatisticsCollection::iterator it; 272 for (it = begin(); it != end(); ++it) { 273 UidStatistics *u = *it; 274 if ((uid == uid_all) || (uid == u->getUid())) { 275 sizes += u->sizes(pid); 276 } 277 } 278 return sizes; 279} 280 281size_t LidStatistics::elements(uid_t uid, pid_t pid) { 282 size_t elements = 0; 283 UidStatisticsCollection::iterator it; 284 for (it = begin(); it != end(); ++it) { 285 UidStatistics *u = *it; 286 if ((uid == uid_all) || (uid == u->getUid())) { 287 elements += u->elements(pid); 288 } 289 } 290 return elements; 291} 292 293size_t LidStatistics::sizesTotal(uid_t uid, pid_t pid) { 294 size_t sizes = 0; 295 UidStatisticsCollection::iterator it; 296 for (it = begin(); it != end(); ++it) { 297 UidStatistics *u = *it; 298 if ((uid == uid_all) || (uid == u->getUid())) { 299 sizes += u->sizesTotal(pid); 300 } 301 } 302 return sizes; 303} 304 305size_t LidStatistics::elementsTotal(uid_t uid, pid_t pid) { 306 size_t elements = 0; 307 UidStatisticsCollection::iterator it; 308 for (it = begin(); it != end(); ++it) { 309 UidStatistics *u = *it; 310 if ((uid == uid_all) || (uid == u->getUid())) { 311 elements += u->elementsTotal(pid); 312 } 313 } 314 return elements; 315} 316 317LogStatistics::LogStatistics() 318 : start(CLOCK_MONOTONIC) { 319 log_id_for_each(i) { 320 mSizes[i] = 0; 321 mElements[i] = 0; 322 } 323 324 dgram_qlen_statistics = false; 325 for(unsigned short bucket = 0; dgram_qlen(bucket); ++bucket) { 326 mMinimum[bucket].tv_sec = (uint32_t)-1; 327 mMinimum[bucket].tv_nsec = 999999999UL; 328 } 329} 330 331// Each bucket below represents a dgram_qlen of log messages. By 332// finding the minimum period of time from start to finish 333// of each dgram_qlen, we can get a performance expectation for 334// the user space logger. The net result is that the period 335// of time divided by the dgram_qlen will give us the average time 336// between log messages; at the point where the average time 337// is greater than the throughput capability of the logger 338// we will not longer require the benefits of the FIFO formed 339// by max_dgram_qlen. We will also expect to see a very visible 340// knee in the average time between log messages at this point, 341// so we do not necessarily have to compare the rate against the 342// measured performance (BM_log_maximum_retry) of the logger. 343// 344// for example (reformatted): 345// 346// Minimum time between log events per dgram_qlen: 347// 1 2 3 5 10 20 30 50 100 200 300 400 500 600 348// 5u2 12u 13u 15u 16u 27u 30u 36u 407u 3m1 3m3 3m9 3m9 5m5 349// 350// demonstrates a clear knee rising at 100, so this means that for this 351// case max_dgram_qlen = 100 would be more than sufficient to handle the 352// worst that the system could stuff into the logger. The 353// BM_log_maximum_retry performance (derated by the log collection) on the 354// same system was 33.2us so we would almost be fine with max_dgram_qlen = 50. 355// BM_log_maxumum_retry with statistics off is roughly 20us, so 356// max_dgram_qlen = 20 would work. We will be more than willing to have 357// a large engineering margin so the rule of thumb that lead us to 100 is 358// fine. 359// 360// bucket dgram_qlen are tuned for /proc/sys/net/unix/max_dgram_qlen = 300 361const unsigned short LogStatistics::mBuckets[] = { 362 1, 2, 3, 5, 10, 20, 30, 50, 100, 200, 300, 400, 500, 600 363}; 364 365unsigned short LogStatistics::dgram_qlen(unsigned short bucket) { 366 if (bucket >= sizeof(mBuckets) / sizeof(mBuckets[0])) { 367 return 0; 368 } 369 return mBuckets[bucket]; 370} 371 372unsigned long long LogStatistics::minimum(unsigned short bucket) { 373 if (mMinimum[bucket].tv_sec == LONG_MAX) { 374 return 0; 375 } 376 return mMinimum[bucket].nsec(); 377} 378 379void LogStatistics::recordDiff(log_time diff, unsigned short bucket) { 380 if ((diff.tv_sec || diff.tv_nsec) && (mMinimum[bucket] > diff)) { 381 mMinimum[bucket] = diff; 382 } 383} 384 385void LogStatistics::add(unsigned short size, 386 log_id_t log_id, uid_t uid, pid_t pid) { 387 mSizes[log_id] += size; 388 ++mElements[log_id]; 389 id(log_id).add(size, uid, pid); 390} 391 392void LogStatistics::subtract(unsigned short size, 393 log_id_t log_id, uid_t uid, pid_t pid) { 394 mSizes[log_id] -= size; 395 --mElements[log_id]; 396 id(log_id).subtract(size, uid, pid); 397} 398 399size_t LogStatistics::sizes(log_id_t log_id, uid_t uid, pid_t pid) { 400 if (log_id != log_id_all) { 401 return id(log_id).sizes(uid, pid); 402 } 403 size_t sizes = 0; 404 log_id_for_each(i) { 405 sizes += id(i).sizes(uid, pid); 406 } 407 return sizes; 408} 409 410size_t LogStatistics::elements(log_id_t log_id, uid_t uid, pid_t pid) { 411 if (log_id != log_id_all) { 412 return id(log_id).elements(uid, pid); 413 } 414 size_t elements = 0; 415 log_id_for_each(i) { 416 elements += id(i).elements(uid, pid); 417 } 418 return elements; 419} 420 421size_t LogStatistics::sizesTotal(log_id_t log_id, uid_t uid, pid_t pid) { 422 if (log_id != log_id_all) { 423 return id(log_id).sizesTotal(uid, pid); 424 } 425 size_t sizes = 0; 426 log_id_for_each(i) { 427 sizes += id(i).sizesTotal(uid, pid); 428 } 429 return sizes; 430} 431 432size_t LogStatistics::elementsTotal(log_id_t log_id, uid_t uid, pid_t pid) { 433 if (log_id != log_id_all) { 434 return id(log_id).elementsTotal(uid, pid); 435 } 436 size_t elements = 0; 437 log_id_for_each(i) { 438 elements += id(i).elementsTotal(uid, pid); 439 } 440 return elements; 441} 442 443void LogStatistics::format(char **buf, 444 uid_t uid, unsigned int logMask, log_time oldest) { 445 static const unsigned short spaces_current = 13; 446 static const unsigned short spaces_total = 19; 447 448 if (*buf) { 449 free(buf); 450 *buf = NULL; 451 } 452 453 android::String8 string(" span -> size/num"); 454 size_t oldLength; 455 short spaces = 2; 456 457 log_id_for_each(i) { 458 if (logMask & (1 << i)) { 459 oldLength = string.length(); 460 if (spaces < 0) { 461 spaces = 0; 462 } 463 string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i)); 464 spaces += spaces_total + oldLength - string.length(); 465 } 466 } 467 468 spaces = 1; 469 log_time t(CLOCK_MONOTONIC); 470 unsigned long long d = t.nsec() - start.nsec(); 471 string.appendFormat("\nTotal%4llu:%02llu:%02llu.%09llu", 472 d / NS_PER_SEC / 60 / 60, (d / NS_PER_SEC / 60) % 60, 473 (d / NS_PER_SEC) % 60, d % NS_PER_SEC); 474 475 log_id_for_each(i) { 476 if (!(logMask & (1 << i))) { 477 continue; 478 } 479 oldLength = string.length(); 480 if (spaces < 0) { 481 spaces = 0; 482 } 483 string.appendFormat("%*s%zu/%zu", spaces, "", 484 sizesTotal(i), elementsTotal(i)); 485 spaces += spaces_total + oldLength - string.length(); 486 } 487 488 spaces = 1; 489 d = t.nsec() - oldest.nsec(); 490 string.appendFormat("\nNow%6llu:%02llu:%02llu.%09llu", 491 d / NS_PER_SEC / 60 / 60, (d / NS_PER_SEC / 60) % 60, 492 (d / NS_PER_SEC) % 60, d % NS_PER_SEC); 493 494 log_id_for_each(i) { 495 if (!(logMask & (1 << i))) { 496 continue; 497 } 498 499 size_t els = elements(i); 500 if (els) { 501 oldLength = string.length(); 502 if (spaces < 0) { 503 spaces = 0; 504 } 505 string.appendFormat("%*s%zu/%zu", spaces, "", sizes(i), els); 506 spaces -= string.length() - oldLength; 507 } 508 spaces += spaces_total; 509 } 510 511 if (dgram_qlen_statistics) { 512 const unsigned short spaces_time = 6; 513 const unsigned long long max_seconds = 100000; 514 spaces = 0; 515 string.append("\n\nMinimum time between log events per dgram_qlen:\n"); 516 for(unsigned short i = 0; dgram_qlen(i); ++i) { 517 oldLength = string.length(); 518 if (spaces < 0) { 519 spaces = 0; 520 } 521 string.appendFormat("%*s%u", spaces, "", dgram_qlen(i)); 522 spaces += spaces_time + oldLength - string.length(); 523 } 524 string.append("\n"); 525 spaces = 0; 526 unsigned short n; 527 for(unsigned short i = 0; (n = dgram_qlen(i)); ++i) { 528 unsigned long long duration = minimum(i); 529 if (duration) { 530 duration /= n; 531 if (duration >= (NS_PER_SEC * max_seconds)) { 532 duration = NS_PER_SEC * (max_seconds - 1); 533 } 534 oldLength = string.length(); 535 if (spaces < 0) { 536 spaces = 0; 537 } 538 string.appendFormat("%*s", spaces, ""); 539 if (duration >= (NS_PER_SEC * 10)) { 540 string.appendFormat("%llu", 541 (duration + (NS_PER_SEC / 2)) 542 / NS_PER_SEC); 543 } else if (duration >= (NS_PER_SEC / (1000 / 10))) { 544 string.appendFormat("%llum", 545 (duration + (NS_PER_SEC / 2 / 1000)) 546 / (NS_PER_SEC / 1000)); 547 } else if (duration >= (NS_PER_SEC / (1000000 / 10))) { 548 string.appendFormat("%lluu", 549 (duration + (NS_PER_SEC / 2 / 1000000)) 550 / (NS_PER_SEC / 1000000)); 551 } else { 552 string.appendFormat("%llun", duration); 553 } 554 spaces -= string.length() - oldLength; 555 } 556 spaces += spaces_time; 557 } 558 } 559 560 log_id_for_each(i) { 561 if (!(logMask & (1 << i))) { 562 continue; 563 } 564 565 bool header = false; 566 bool first = true; 567 568 UidStatisticsCollection::iterator ut; 569 for(ut = id(i).begin(); ut != id(i).end(); ++ut) { 570 UidStatistics *up = *ut; 571 if ((uid != AID_ROOT) && (uid != up->getUid())) { 572 continue; 573 } 574 575 PidStatisticsCollection::iterator pt = up->begin(); 576 if (pt == up->end()) { 577 continue; 578 } 579 580 android::String8 intermediate; 581 582 if (!header) { 583 // header below tuned to match spaces_total and spaces_current 584 spaces = 0; 585 intermediate = string.format("%s: UID/PID Total size/num", 586 android_log_id_to_name(i)); 587 string.appendFormat("\n\n%-31sNow " 588 "UID/PID[?] Total Now", 589 intermediate.string()); 590 intermediate.clear(); 591 header = true; 592 } 593 594 bool oneline = ++pt == up->end(); 595 --pt; 596 597 if (!oneline) { 598 first = true; 599 } else if (!first && (spaces > 0)) { 600 string.appendFormat("%*s", spaces, ""); 601 } 602 spaces = 0; 603 604 uid_t u = up->getUid(); 605 pid_t p = (*pt)->getPid(); 606 607 intermediate = string.format(oneline 608 ? ((p == PidStatistics::gone) 609 ? "%d/?" 610 : "%d/%d") 611 : "%d", 612 u, p); 613 string.appendFormat((first) ? "\n%-12s" : "%-12s", 614 intermediate.string()); 615 intermediate.clear(); 616 617 size_t elsTotal = up->elementsTotal(); 618 oldLength = string.length(); 619 string.appendFormat("%zu/%zu", up->sizesTotal(), elsTotal); 620 spaces += spaces_total + oldLength - string.length(); 621 622 size_t els = up->elements(); 623 if (els == elsTotal) { 624 if (spaces < 0) { 625 spaces = 0; 626 } 627 string.appendFormat("%*s=", spaces, ""); 628 spaces = -1; 629 } else if (els) { 630 oldLength = string.length(); 631 if (spaces < 0) { 632 spaces = 0; 633 } 634 string.appendFormat("%*s%zu/%zu", spaces, "", up->sizes(), els); 635 spaces -= string.length() - oldLength; 636 } 637 spaces += spaces_current; 638 639 first = !first; 640 641 if (oneline) { 642 continue; 643 } 644 645 size_t gone_szs = 0; 646 size_t gone_els = 0; 647 648 for(; pt != up->end(); ++pt) { 649 PidStatistics *pp = *pt; 650 pid_t p = pp->getPid(); 651 652 // If a PID no longer has any current logs, and is not 653 // active anymore, skip & report totals for gone. 654 elsTotal = pp->elementsTotal(); 655 size_t szsTotal = pp->sizesTotal(); 656 if (p == pp->gone) { 657 gone_szs += szsTotal; 658 gone_els += elsTotal; 659 continue; 660 } 661 els = pp->elements(); 662 bool gone = kill(p, 0); 663 if (gone && (els == 0)) { 664 // ToDo: garbage collection: move this statistical bucket 665 // from its current UID/PID to UID/? (races and 666 // wrap around are our achilles heel). Below is 667 // merely lipservice to catch PIDs that were still 668 // around when the stats were pruned to zero. 669 gone_szs += szsTotal; 670 gone_els += elsTotal; 671 continue; 672 } 673 674 if (!first && (spaces > 0)) { 675 string.appendFormat("%*s", spaces, ""); 676 } 677 spaces = 0; 678 679 intermediate = string.format((gone) ? "%d/%d?" : "%d/%d", u, p); 680 string.appendFormat((first) ? "\n%-12s" : "%-12s", 681 intermediate.string()); 682 intermediate.clear(); 683 684 oldLength = string.length(); 685 string.appendFormat("%zu/%zu", szsTotal, elsTotal); 686 spaces += spaces_total + oldLength - string.length(); 687 688 if (els == elsTotal) { 689 if (spaces < 0) { 690 spaces = 0; 691 } 692 string.appendFormat("%*s=", spaces, ""); 693 spaces = -1; 694 } else if (els) { 695 oldLength = string.length(); 696 if (spaces < 0) { 697 spaces = 0; 698 } 699 string.appendFormat("%*s%zu/%zu", spaces, "", 700 pp->sizes(), els); 701 spaces -= string.length() - oldLength; 702 } 703 spaces += spaces_current; 704 705 first = !first; 706 } 707 708 if (gone_els) { 709 if (!first && (spaces > 0)) { 710 string.appendFormat("%*s", spaces, ""); 711 } 712 713 intermediate = string.format("%d/?", u); 714 string.appendFormat((first) ? "\n%-12s" : "%-12s", 715 intermediate.string()); 716 intermediate.clear(); 717 718 spaces = spaces_total + spaces_current; 719 720 oldLength = string.length(); 721 string.appendFormat("%zu/%zu", gone_szs, gone_els); 722 spaces -= string.length() - oldLength; 723 724 first = !first; 725 } 726 } 727 } 728 729 *buf = strdup(string.string()); 730} 731 732uid_t LogStatistics::pidToUid(pid_t pid) { 733 log_id_for_each(i) { 734 LidStatistics &l = id(i); 735 UidStatisticsCollection::iterator iu; 736 for (iu = l.begin(); iu != l.end(); ++iu) { 737 UidStatistics &u = *(*iu); 738 PidStatisticsCollection::iterator ip; 739 for (ip = u.begin(); ip != u.end(); ++ip) { 740 if ((*ip)->getPid() == pid) { 741 return u.getUid(); 742 } 743 } 744 } 745 } 746 return getuid(); // associate this with the logger 747} 748