blob: 53036e6694773adfff547c8bd607166db06d563e [file] [log] [blame]
Mark Salyzyn34facab2014-02-06 14:48:50 -08001/*
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
Mark Salyzyn9a038632014-04-07 07:05:40 -070017#include <fcntl.h>
Elliott Hughesa744b052015-01-28 11:37:57 -080018#include <malloc.h>
Mark Salyzyn34facab2014-02-06 14:48:50 -080019#include <stdarg.h>
20#include <time.h>
21
22#include <log/logger.h>
23#include <private/android_filesystem_config.h>
24#include <utils/String8.h>
25
26#include "LogStatistics.h"
27
Mark Salyzyn9a038632014-04-07 07:05:40 -070028PidStatistics::PidStatistics(pid_t pid, char *name)
Mark Salyzyn34facab2014-02-06 14:48:50 -080029 : pid(pid)
30 , mSizesTotal(0)
31 , mElementsTotal(0)
32 , mSizes(0)
Mark Salyzyn9a038632014-04-07 07:05:40 -070033 , mElements(0)
34 , name(name)
Mark Salyzynfdabe722014-04-21 10:09:42 -070035 , mGone(false)
Mark Salyzyn9a038632014-04-07 07:05:40 -070036{ }
37
38#ifdef DO_NOT_ERROR_IF_PIDSTATISTICS_USES_A_COPY_CONSTRUCTOR
39PidStatistics::PidStatistics(const PidStatistics &copy)
40 : pid(copy->pid)
41 , name(copy->name ? strdup(copy->name) : NULL)
42 , mSizesTotal(copy->mSizesTotal)
43 , mElementsTotal(copy->mElementsTotal)
44 , mSizes(copy->mSizes)
45 , mElements(copy->mElements)
Mark Salyzynfdabe722014-04-21 10:09:42 -070046 , mGone(copy->mGone)
Mark Salyzyn9a038632014-04-07 07:05:40 -070047{ }
48#endif
49
50PidStatistics::~PidStatistics() {
51 free(name);
52}
53
Mark Salyzynfdabe722014-04-21 10:09:42 -070054bool PidStatistics::pidGone() {
Mark Salyzyne72c6e42014-09-21 14:22:18 -070055 if (mGone || (pid == gone)) {
Mark Salyzynfdabe722014-04-21 10:09:42 -070056 return true;
57 }
Mark Salyzyndf5aa612014-09-21 14:22:18 -070058 if (pid == 0) {
59 return false;
60 }
Mark Salyzynfdabe722014-04-21 10:09:42 -070061 if (kill(pid, 0) && (errno != EPERM)) {
62 mGone = true;
63 return true;
64 }
65 return false;
66}
67
Mark Salyzyn9a038632014-04-07 07:05:40 -070068void PidStatistics::setName(char *new_name) {
69 free(name);
70 name = new_name;
71}
Mark Salyzyn34facab2014-02-06 14:48:50 -080072
73void PidStatistics::add(unsigned short size) {
74 mSizesTotal += size;
75 ++mElementsTotal;
76 mSizes += size;
77 ++mElements;
78}
79
80bool PidStatistics::subtract(unsigned short size) {
81 mSizes -= size;
82 --mElements;
Mark Salyzynfdabe722014-04-21 10:09:42 -070083 return (mElements == 0) && pidGone();
Mark Salyzyn34facab2014-02-06 14:48:50 -080084}
85
86void PidStatistics::addTotal(size_t size, size_t element) {
87 if (pid == gone) {
88 mSizesTotal += size;
89 mElementsTotal += element;
90 }
91}
92
Mark Salyzyn9a038632014-04-07 07:05:40 -070093// must call free to release return value
Mark Salyzyne72c6e42014-09-21 14:22:18 -070094// If only we could sniff our own logs for:
95// <time> <pid> <pid> E AndroidRuntime: Process: <name>, PID: <pid>
96// which debuggerd prints as a process is crashing.
Mark Salyzyn9a038632014-04-07 07:05:40 -070097char *PidStatistics::pidToName(pid_t pid) {
98 char *retval = NULL;
Mark Salyzyndf5aa612014-09-21 14:22:18 -070099 if (pid == 0) { // special case from auditd for kernel
100 retval = strdup("logd.auditd");
101 } else if (pid != gone) {
Mark Salyzyn9a038632014-04-07 07:05:40 -0700102 char buffer[512];
103 snprintf(buffer, sizeof(buffer), "/proc/%u/cmdline", pid);
104 int fd = open(buffer, O_RDONLY);
105 if (fd >= 0) {
106 ssize_t ret = read(fd, buffer, sizeof(buffer));
107 if (ret > 0) {
108 buffer[sizeof(buffer)-1] = '\0';
109 // frameworks intermediate state
110 if (strcmp(buffer, "<pre-initialized>")) {
111 retval = strdup(buffer);
112 }
113 }
114 close(fd);
115 }
116 }
117 return retval;
118}
119
Mark Salyzyn34facab2014-02-06 14:48:50 -0800120UidStatistics::UidStatistics(uid_t uid)
Mark Salyzync8a576c2014-04-04 16:35:59 -0700121 : uid(uid)
122 , mSizes(0)
123 , mElements(0) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800124 Pids.clear();
125}
126
127UidStatistics::~UidStatistics() {
128 PidStatisticsCollection::iterator it;
129 for (it = begin(); it != end();) {
130 delete (*it);
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700131 it = erase(it);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800132 }
133}
134
135void UidStatistics::add(unsigned short size, pid_t pid) {
Mark Salyzync8a576c2014-04-04 16:35:59 -0700136 mSizes += size;
137 ++mElements;
138
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700139 PidStatistics *p = NULL;
Mark Salyzyn34facab2014-02-06 14:48:50 -0800140 PidStatisticsCollection::iterator last;
141 PidStatisticsCollection::iterator it;
142 for (last = it = begin(); it != end(); last = it, ++it) {
143 p = *it;
144 if (pid == p->getPid()) {
145 p->add(size);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800146 return;
147 }
148 }
Mark Salyzync8a576c2014-04-04 16:35:59 -0700149 // insert if the gone entry.
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700150 bool insert_before_last = (last != it) && p && (p->getPid() == p->gone);
Mark Salyzyn9a038632014-04-07 07:05:40 -0700151 p = new PidStatistics(pid, pidToName(pid));
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700152 if (insert_before_last) {
153 insert(last, p);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800154 } else {
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700155 push_back(p);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800156 }
157 p->add(size);
158}
159
160void UidStatistics::subtract(unsigned short size, pid_t pid) {
Mark Salyzync8a576c2014-04-04 16:35:59 -0700161 mSizes -= size;
162 --mElements;
163
Mark Salyzyn34facab2014-02-06 14:48:50 -0800164 PidStatisticsCollection::iterator it;
165 for (it = begin(); it != end(); ++it) {
166 PidStatistics *p = *it;
167 if (pid == p->getPid()) {
168 if (p->subtract(size)) {
169 size_t szsTotal = p->sizesTotal();
170 size_t elsTotal = p->elementsTotal();
171 delete p;
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700172 erase(it);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800173 it = end();
174 --it;
175 if (it == end()) {
176 p = new PidStatistics(p->gone);
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700177 push_back(p);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800178 } else {
179 p = *it;
180 if (p->getPid() != p->gone) {
181 p = new PidStatistics(p->gone);
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700182 push_back(p);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800183 }
184 }
185 p->addTotal(szsTotal, elsTotal);
186 }
187 return;
188 }
189 }
190}
191
Mark Salyzync8a576c2014-04-04 16:35:59 -0700192void UidStatistics::sort() {
193 for (bool pass = true; pass;) {
194 pass = false;
195 PidStatisticsCollection::iterator it = begin();
196 if (it != end()) {
197 PidStatisticsCollection::iterator lt = it;
198 PidStatistics *l = (*lt);
199 while (++it != end()) {
200 PidStatistics *n = (*it);
201 if ((n->getPid() != n->gone) && (n->sizes() > l->sizes())) {
202 pass = true;
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700203 erase(it);
204 insert(lt, n);
Mark Salyzync8a576c2014-04-04 16:35:59 -0700205 it = lt;
206 n = l;
207 }
208 lt = it;
209 l = n;
210 }
211 }
212 }
213}
214
Mark Salyzyn34facab2014-02-06 14:48:50 -0800215size_t UidStatistics::sizes(pid_t pid) {
Mark Salyzync8a576c2014-04-04 16:35:59 -0700216 if (pid == pid_all) {
217 return sizes();
218 }
219
Mark Salyzyn34facab2014-02-06 14:48:50 -0800220 PidStatisticsCollection::iterator it;
221 for (it = begin(); it != end(); ++it) {
222 PidStatistics *p = *it;
Mark Salyzync8a576c2014-04-04 16:35:59 -0700223 if (pid == p->getPid()) {
224 return p->sizes();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800225 }
226 }
Mark Salyzync8a576c2014-04-04 16:35:59 -0700227 return 0;
Mark Salyzyn34facab2014-02-06 14:48:50 -0800228}
229
230size_t UidStatistics::elements(pid_t pid) {
Mark Salyzync8a576c2014-04-04 16:35:59 -0700231 if (pid == pid_all) {
232 return elements();
233 }
234
Mark Salyzyn34facab2014-02-06 14:48:50 -0800235 PidStatisticsCollection::iterator it;
236 for (it = begin(); it != end(); ++it) {
237 PidStatistics *p = *it;
Mark Salyzync8a576c2014-04-04 16:35:59 -0700238 if (pid == p->getPid()) {
239 return p->elements();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800240 }
241 }
Mark Salyzync8a576c2014-04-04 16:35:59 -0700242 return 0;
Mark Salyzyn34facab2014-02-06 14:48:50 -0800243}
244
245size_t UidStatistics::sizesTotal(pid_t pid) {
246 size_t sizes = 0;
247 PidStatisticsCollection::iterator it;
248 for (it = begin(); it != end(); ++it) {
249 PidStatistics *p = *it;
250 if ((pid == pid_all) || (pid == p->getPid())) {
251 sizes += p->sizesTotal();
252 }
253 }
254 return sizes;
255}
256
257size_t UidStatistics::elementsTotal(pid_t pid) {
258 size_t elements = 0;
259 PidStatisticsCollection::iterator it;
260 for (it = begin(); it != end(); ++it) {
261 PidStatistics *p = *it;
262 if ((pid == pid_all) || (pid == p->getPid())) {
263 elements += p->elementsTotal();
264 }
265 }
266 return elements;
267}
268
269LidStatistics::LidStatistics() {
270 Uids.clear();
271}
272
273LidStatistics::~LidStatistics() {
274 UidStatisticsCollection::iterator it;
275 for (it = begin(); it != end();) {
276 delete (*it);
277 it = Uids.erase(it);
278 }
279}
280
281void LidStatistics::add(unsigned short size, uid_t uid, pid_t pid) {
282 UidStatistics *u;
283 UidStatisticsCollection::iterator it;
284 UidStatisticsCollection::iterator last;
285
286 if (uid == (uid_t) -1) { // init
287 uid = (uid_t) AID_ROOT;
288 }
289
290 for (last = it = begin(); it != end(); last = it, ++it) {
291 u = *it;
292 if (uid == u->getUid()) {
293 u->add(size, pid);
294 if ((last != it) && ((*last)->sizesTotal() < u->sizesTotal())) {
295 Uids.erase(it);
296 Uids.insert(last, u);
297 }
298 return;
299 }
300 }
301 u = new UidStatistics(uid);
302 if ((last != it) && ((*last)->sizesTotal() < (size_t) size)) {
303 Uids.insert(last, u);
304 } else {
305 Uids.push_back(u);
306 }
307 u->add(size, pid);
308}
309
310void LidStatistics::subtract(unsigned short size, uid_t uid, pid_t pid) {
Mark Salyzynf48ea7c2014-09-22 10:58:36 -0700311 if (uid == (uid_t) -1) { // init
312 uid = (uid_t) AID_ROOT;
313 }
314
Mark Salyzyn34facab2014-02-06 14:48:50 -0800315 UidStatisticsCollection::iterator it;
316 for (it = begin(); it != end(); ++it) {
317 UidStatistics *u = *it;
318 if (uid == u->getUid()) {
319 u->subtract(size, pid);
320 return;
321 }
322 }
323}
324
Mark Salyzync8a576c2014-04-04 16:35:59 -0700325void LidStatistics::sort() {
326 for (bool pass = true; pass;) {
327 pass = false;
328 UidStatisticsCollection::iterator it = begin();
329 if (it != end()) {
330 UidStatisticsCollection::iterator lt = it;
331 UidStatistics *l = (*lt);
332 while (++it != end()) {
333 UidStatistics *n = (*it);
334 if (n->sizes() > l->sizes()) {
335 pass = true;
336 Uids.erase(it);
337 Uids.insert(lt, n);
338 it = lt;
339 n = l;
340 }
341 lt = it;
342 l = n;
343 }
344 }
345 }
346}
347
Mark Salyzyn34facab2014-02-06 14:48:50 -0800348size_t LidStatistics::sizes(uid_t uid, pid_t pid) {
349 size_t sizes = 0;
350 UidStatisticsCollection::iterator it;
351 for (it = begin(); it != end(); ++it) {
352 UidStatistics *u = *it;
353 if ((uid == uid_all) || (uid == u->getUid())) {
354 sizes += u->sizes(pid);
355 }
356 }
357 return sizes;
358}
359
360size_t LidStatistics::elements(uid_t uid, pid_t pid) {
361 size_t elements = 0;
362 UidStatisticsCollection::iterator it;
363 for (it = begin(); it != end(); ++it) {
364 UidStatistics *u = *it;
365 if ((uid == uid_all) || (uid == u->getUid())) {
366 elements += u->elements(pid);
367 }
368 }
369 return elements;
370}
371
372size_t LidStatistics::sizesTotal(uid_t uid, pid_t pid) {
373 size_t sizes = 0;
374 UidStatisticsCollection::iterator it;
375 for (it = begin(); it != end(); ++it) {
376 UidStatistics *u = *it;
377 if ((uid == uid_all) || (uid == u->getUid())) {
378 sizes += u->sizesTotal(pid);
379 }
380 }
381 return sizes;
382}
383
384size_t LidStatistics::elementsTotal(uid_t uid, pid_t pid) {
385 size_t elements = 0;
386 UidStatisticsCollection::iterator it;
387 for (it = begin(); it != end(); ++it) {
388 UidStatistics *u = *it;
389 if ((uid == uid_all) || (uid == u->getUid())) {
390 elements += u->elementsTotal(pid);
391 }
392 }
393 return elements;
394}
395
396LogStatistics::LogStatistics()
Mark Salyzynf5fc5092014-09-21 14:22:18 -0700397 : mStatistics(false)
398 , dgramQlenStatistics(false)
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700399 , start(CLOCK_MONOTONIC) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800400 log_id_for_each(i) {
401 mSizes[i] = 0;
402 mElements[i] = 0;
403 }
Mark Salyzyne457b742014-02-19 17:18:31 -0800404
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700405 for(unsigned short bucket = 0; dgramQlen(bucket); ++bucket) {
Mark Salyzyn3cb54982014-04-30 09:21:54 -0700406 mMinimum[bucket].tv_sec = mMinimum[bucket].tv_sec_max;
407 mMinimum[bucket].tv_nsec = mMinimum[bucket].tv_nsec_max;
Mark Salyzyne457b742014-02-19 17:18:31 -0800408 }
409}
410
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700411// Each bucket below represents a dgramQlen of log messages. By
Mark Salyzyne457b742014-02-19 17:18:31 -0800412// finding the minimum period of time from start to finish
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700413// of each dgramQlen, we can get a performance expectation for
Mark Salyzyne457b742014-02-19 17:18:31 -0800414// the user space logger. The net result is that the period
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700415// of time divided by the dgramQlen will give us the average time
Mark Salyzyne457b742014-02-19 17:18:31 -0800416// between log messages; at the point where the average time
417// is greater than the throughput capability of the logger
418// we will not longer require the benefits of the FIFO formed
419// by max_dgram_qlen. We will also expect to see a very visible
420// knee in the average time between log messages at this point,
421// so we do not necessarily have to compare the rate against the
422// measured performance (BM_log_maximum_retry) of the logger.
423//
424// for example (reformatted):
425//
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700426// Minimum time between log events per dgramQlen:
Mark Salyzyne457b742014-02-19 17:18:31 -0800427// 1 2 3 5 10 20 30 50 100 200 300 400 500 600
428// 5u2 12u 13u 15u 16u 27u 30u 36u 407u 3m1 3m3 3m9 3m9 5m5
429//
430// demonstrates a clear knee rising at 100, so this means that for this
431// case max_dgram_qlen = 100 would be more than sufficient to handle the
432// worst that the system could stuff into the logger. The
433// BM_log_maximum_retry performance (derated by the log collection) on the
434// same system was 33.2us so we would almost be fine with max_dgram_qlen = 50.
435// BM_log_maxumum_retry with statistics off is roughly 20us, so
436// max_dgram_qlen = 20 would work. We will be more than willing to have
437// a large engineering margin so the rule of thumb that lead us to 100 is
438// fine.
439//
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700440// bucket dgramQlen are tuned for /proc/sys/net/unix/max_dgram_qlen = 300
Mark Salyzyne457b742014-02-19 17:18:31 -0800441const unsigned short LogStatistics::mBuckets[] = {
442 1, 2, 3, 5, 10, 20, 30, 50, 100, 200, 300, 400, 500, 600
443};
444
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700445unsigned short LogStatistics::dgramQlen(unsigned short bucket) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800446 if (bucket >= sizeof(mBuckets) / sizeof(mBuckets[0])) {
447 return 0;
448 }
449 return mBuckets[bucket];
450}
451
452unsigned long long LogStatistics::minimum(unsigned short bucket) {
Mark Salyzyn3cb54982014-04-30 09:21:54 -0700453 if (mMinimum[bucket].tv_sec == mMinimum[bucket].tv_sec_max) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800454 return 0;
455 }
456 return mMinimum[bucket].nsec();
457}
458
459void LogStatistics::recordDiff(log_time diff, unsigned short bucket) {
460 if ((diff.tv_sec || diff.tv_nsec) && (mMinimum[bucket] > diff)) {
461 mMinimum[bucket] = diff;
462 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800463}
464
465void LogStatistics::add(unsigned short size,
466 log_id_t log_id, uid_t uid, pid_t pid) {
467 mSizes[log_id] += size;
468 ++mElements[log_id];
Mark Salyzynf5fc5092014-09-21 14:22:18 -0700469 if (!mStatistics) {
470 return;
471 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800472 id(log_id).add(size, uid, pid);
473}
474
475void LogStatistics::subtract(unsigned short size,
476 log_id_t log_id, uid_t uid, pid_t pid) {
477 mSizes[log_id] -= size;
478 --mElements[log_id];
Mark Salyzynf5fc5092014-09-21 14:22:18 -0700479 if (!mStatistics) {
480 return;
481 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800482 id(log_id).subtract(size, uid, pid);
483}
484
485size_t LogStatistics::sizes(log_id_t log_id, uid_t uid, pid_t pid) {
486 if (log_id != log_id_all) {
487 return id(log_id).sizes(uid, pid);
488 }
489 size_t sizes = 0;
490 log_id_for_each(i) {
491 sizes += id(i).sizes(uid, pid);
492 }
493 return sizes;
494}
495
496size_t LogStatistics::elements(log_id_t log_id, uid_t uid, pid_t pid) {
497 if (log_id != log_id_all) {
498 return id(log_id).elements(uid, pid);
499 }
500 size_t elements = 0;
501 log_id_for_each(i) {
502 elements += id(i).elements(uid, pid);
503 }
504 return elements;
505}
506
507size_t LogStatistics::sizesTotal(log_id_t log_id, uid_t uid, pid_t pid) {
508 if (log_id != log_id_all) {
509 return id(log_id).sizesTotal(uid, pid);
510 }
511 size_t sizes = 0;
512 log_id_for_each(i) {
513 sizes += id(i).sizesTotal(uid, pid);
514 }
515 return sizes;
516}
517
518size_t LogStatistics::elementsTotal(log_id_t log_id, uid_t uid, pid_t pid) {
519 if (log_id != log_id_all) {
520 return id(log_id).elementsTotal(uid, pid);
521 }
522 size_t elements = 0;
523 log_id_for_each(i) {
524 elements += id(i).elementsTotal(uid, pid);
525 }
526 return elements;
527}
528
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800529void LogStatistics::format(char **buf,
530 uid_t uid, unsigned int logMask, log_time oldest) {
Mark Salyzyn9a038632014-04-07 07:05:40 -0700531 static const unsigned short spaces_current = 13;
532 static const unsigned short spaces_total = 19;
Mark Salyzyn34facab2014-02-06 14:48:50 -0800533
534 if (*buf) {
Greg Hackmann239605e2014-04-06 21:25:58 -0700535 free(*buf);
Mark Salyzyn34facab2014-02-06 14:48:50 -0800536 *buf = NULL;
537 }
538
539 android::String8 string(" span -> size/num");
540 size_t oldLength;
541 short spaces = 2;
542
543 log_id_for_each(i) {
Arseniy Antonovc3ce2242014-09-03 17:29:20 +0400544 if (!(logMask & (1 << i))) {
Mark Salyzync8a576c2014-04-04 16:35:59 -0700545 continue;
546 }
547 oldLength = string.length();
548 if (spaces < 0) {
549 spaces = 0;
550 }
551 string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i));
552 spaces += spaces_total + oldLength - string.length();
553
554 LidStatistics &l = id(i);
555 l.sort();
556
557 UidStatisticsCollection::iterator iu;
558 for (iu = l.begin(); iu != l.end(); ++iu) {
559 (*iu)->sort();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800560 }
561 }
562
563 spaces = 1;
564 log_time t(CLOCK_MONOTONIC);
Mark Salyzynf5fc5092014-09-21 14:22:18 -0700565 unsigned long long d;
566 if (mStatistics) {
567 d = t.nsec() - start.nsec();
568 string.appendFormat("\nTotal%4llu:%02llu:%02llu.%09llu",
Mark Salyzyn34facab2014-02-06 14:48:50 -0800569 d / NS_PER_SEC / 60 / 60, (d / NS_PER_SEC / 60) % 60,
570 (d / NS_PER_SEC) % 60, d % NS_PER_SEC);
571
Mark Salyzynf5fc5092014-09-21 14:22:18 -0700572 log_id_for_each(i) {
573 if (!(logMask & (1 << i))) {
574 continue;
575 }
576 oldLength = string.length();
577 if (spaces < 0) {
578 spaces = 0;
579 }
580 string.appendFormat("%*s%zu/%zu", spaces, "",
581 sizesTotal(i), elementsTotal(i));
582 spaces += spaces_total + oldLength - string.length();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800583 }
Mark Salyzynf5fc5092014-09-21 14:22:18 -0700584 spaces = 1;
Mark Salyzyn34facab2014-02-06 14:48:50 -0800585 }
586
Mark Salyzyn34facab2014-02-06 14:48:50 -0800587 d = t.nsec() - oldest.nsec();
588 string.appendFormat("\nNow%6llu:%02llu:%02llu.%09llu",
589 d / NS_PER_SEC / 60 / 60, (d / NS_PER_SEC / 60) % 60,
590 (d / NS_PER_SEC) % 60, d % NS_PER_SEC);
591
592 log_id_for_each(i) {
593 if (!(logMask & (1 << i))) {
594 continue;
595 }
596
597 size_t els = elements(i);
598 if (els) {
599 oldLength = string.length();
Mark Salyzyne457b742014-02-19 17:18:31 -0800600 if (spaces < 0) {
601 spaces = 0;
602 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800603 string.appendFormat("%*s%zu/%zu", spaces, "", sizes(i), els);
604 spaces -= string.length() - oldLength;
605 }
606 spaces += spaces_total;
607 }
608
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700609 // Construct list of worst spammers by Pid
610 static const unsigned char num_spammers = 10;
611 bool header = false;
612
613 log_id_for_each(i) {
614 if (!(logMask & (1 << i))) {
615 continue;
616 }
617
618 PidStatisticsCollection pids;
619 pids.clear();
620
621 LidStatistics &l = id(i);
622 UidStatisticsCollection::iterator iu;
623 for (iu = l.begin(); iu != l.end(); ++iu) {
624 UidStatistics &u = *(*iu);
625 PidStatisticsCollection::iterator ip;
626 for (ip = u.begin(); ip != u.end(); ++ip) {
627 PidStatistics *p = (*ip);
628 if (p->getPid() == p->gone) {
629 break;
630 }
631
632 size_t mySizes = p->sizes();
633
634 PidStatisticsCollection::iterator q;
635 unsigned char num = 0;
636 for (q = pids.begin(); q != pids.end(); ++q) {
637 if (mySizes > (*q)->sizes()) {
638 pids.insert(q, p);
639 break;
640 }
641 // do we need to traverse deeper in the list?
642 if (++num > num_spammers) {
643 break;
644 }
645 }
646 if (q == pids.end()) {
647 pids.push_back(p);
648 }
649 }
650 }
651
652 size_t threshold = sizes(i);
653 if (threshold < 65536) {
654 threshold = 65536;
655 }
656 threshold /= 100;
657
658 PidStatisticsCollection::iterator pt = pids.begin();
659
660 for(int line = 0;
661 (pt != pids.end()) && (line < num_spammers);
662 ++line, pt = pids.erase(pt)) {
663 PidStatistics *p = *pt;
664
665 size_t sizes = p->sizes();
666 if (sizes < threshold) {
667 break;
668 }
669
670 char *name = p->getName();
671 pid_t pid = p->getPid();
672 if (!name || !*name) {
673 name = pidToName(pid);
674 if (name) {
675 if (*name) {
676 p->setName(name);
677 } else {
678 free(name);
679 name = NULL;
680 }
681 }
682 }
683
684 if (!header) {
685 string.appendFormat("\n\nChattiest clients:\n"
686 "log id %-*s PID[?] name",
687 spaces_total, "size/total");
688 header = true;
689 }
690
691 size_t sizesTotal = p->sizesTotal();
692
693 android::String8 sz("");
Chih-Hung Hsieh634118e2014-09-12 16:02:28 -0700694 if (sizes == sizesTotal) {
695 sz.appendFormat("%zu", sizes);
696 } else {
697 sz.appendFormat("%zu/%zu", sizes, sizesTotal);
698 }
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700699
700 android::String8 pd("");
Mark Salyzynfdabe722014-04-21 10:09:42 -0700701 pd.appendFormat("%u%c", pid, p->pidGone() ? '?' : ' ');
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700702
703 string.appendFormat("\n%-7s%-*s %-7s%s",
704 line ? "" : android_log_id_to_name(i),
705 spaces_total, sz.string(), pd.string(),
706 name ? name : "");
707 }
708
709 pids.clear();
710 }
711
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700712 if (dgramQlenStatistics) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800713 const unsigned short spaces_time = 6;
714 const unsigned long long max_seconds = 100000;
715 spaces = 0;
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700716 string.append("\n\nMinimum time between log events per max_dgram_qlen:\n");
717 for(unsigned short i = 0; dgramQlen(i); ++i) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800718 oldLength = string.length();
719 if (spaces < 0) {
720 spaces = 0;
721 }
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700722 string.appendFormat("%*s%u", spaces, "", dgramQlen(i));
Mark Salyzyne457b742014-02-19 17:18:31 -0800723 spaces += spaces_time + oldLength - string.length();
724 }
725 string.append("\n");
726 spaces = 0;
727 unsigned short n;
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700728 for(unsigned short i = 0; (n = dgramQlen(i)); ++i) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800729 unsigned long long duration = minimum(i);
730 if (duration) {
731 duration /= n;
732 if (duration >= (NS_PER_SEC * max_seconds)) {
733 duration = NS_PER_SEC * (max_seconds - 1);
734 }
735 oldLength = string.length();
736 if (spaces < 0) {
737 spaces = 0;
738 }
739 string.appendFormat("%*s", spaces, "");
740 if (duration >= (NS_PER_SEC * 10)) {
741 string.appendFormat("%llu",
742 (duration + (NS_PER_SEC / 2))
743 / NS_PER_SEC);
744 } else if (duration >= (NS_PER_SEC / (1000 / 10))) {
745 string.appendFormat("%llum",
746 (duration + (NS_PER_SEC / 2 / 1000))
747 / (NS_PER_SEC / 1000));
748 } else if (duration >= (NS_PER_SEC / (1000000 / 10))) {
749 string.appendFormat("%lluu",
Mark Salyzyne72c6e42014-09-21 14:22:18 -0700750 (duration + (NS_PER_SEC / 2 / 1000000))
751 / (NS_PER_SEC / 1000000));
Mark Salyzyne457b742014-02-19 17:18:31 -0800752 } else {
753 string.appendFormat("%llun", duration);
754 }
755 spaces -= string.length() - oldLength;
756 }
757 spaces += spaces_time;
758 }
759 }
760
Mark Salyzyn34facab2014-02-06 14:48:50 -0800761 log_id_for_each(i) {
762 if (!(logMask & (1 << i))) {
763 continue;
764 }
765
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700766 header = false;
Mark Salyzyn34facab2014-02-06 14:48:50 -0800767 bool first = true;
768
769 UidStatisticsCollection::iterator ut;
770 for(ut = id(i).begin(); ut != id(i).end(); ++ut) {
771 UidStatistics *up = *ut;
772 if ((uid != AID_ROOT) && (uid != up->getUid())) {
773 continue;
774 }
775
776 PidStatisticsCollection::iterator pt = up->begin();
777 if (pt == up->end()) {
778 continue;
779 }
780
781 android::String8 intermediate;
782
783 if (!header) {
784 // header below tuned to match spaces_total and spaces_current
785 spaces = 0;
786 intermediate = string.format("%s: UID/PID Total size/num",
787 android_log_id_to_name(i));
788 string.appendFormat("\n\n%-31sNow "
789 "UID/PID[?] Total Now",
790 intermediate.string());
791 intermediate.clear();
792 header = true;
793 }
794
795 bool oneline = ++pt == up->end();
796 --pt;
797
798 if (!oneline) {
799 first = true;
Mark Salyzyne457b742014-02-19 17:18:31 -0800800 } else if (!first && (spaces > 0)) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800801 string.appendFormat("%*s", spaces, "");
802 }
803 spaces = 0;
804
805 uid_t u = up->getUid();
Mark Salyzynfdabe722014-04-21 10:09:42 -0700806 PidStatistics *pp = *pt;
807 pid_t p = pp->getPid();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800808
Chih-Hung Hsieh634118e2014-09-12 16:02:28 -0700809 if (!oneline) {
810 intermediate = string.format("%d", u);
811 } else if (p == PidStatistics::gone) {
812 intermediate = string.format("%d/?", u);
813 } else if (pp->pidGone()) {
814 intermediate = string.format("%d/%d?", u, p);
815 } else {
816 intermediate = string.format("%d/%d", u, p);
817 }
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700818 string.appendFormat(first ? "\n%-12s" : "%-12s",
Mark Salyzyn34facab2014-02-06 14:48:50 -0800819 intermediate.string());
820 intermediate.clear();
821
822 size_t elsTotal = up->elementsTotal();
823 oldLength = string.length();
824 string.appendFormat("%zu/%zu", up->sizesTotal(), elsTotal);
825 spaces += spaces_total + oldLength - string.length();
826
827 size_t els = up->elements();
828 if (els == elsTotal) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800829 if (spaces < 0) {
830 spaces = 0;
831 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800832 string.appendFormat("%*s=", spaces, "");
833 spaces = -1;
834 } else if (els) {
835 oldLength = string.length();
Mark Salyzyne457b742014-02-19 17:18:31 -0800836 if (spaces < 0) {
837 spaces = 0;
838 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800839 string.appendFormat("%*s%zu/%zu", spaces, "", up->sizes(), els);
840 spaces -= string.length() - oldLength;
841 }
842 spaces += spaces_current;
843
844 first = !first;
845
846 if (oneline) {
847 continue;
848 }
849
850 size_t gone_szs = 0;
851 size_t gone_els = 0;
852
853 for(; pt != up->end(); ++pt) {
Mark Salyzynfdabe722014-04-21 10:09:42 -0700854 pp = *pt;
855 p = pp->getPid();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800856
857 // If a PID no longer has any current logs, and is not
858 // active anymore, skip & report totals for gone.
859 elsTotal = pp->elementsTotal();
860 size_t szsTotal = pp->sizesTotal();
861 if (p == pp->gone) {
862 gone_szs += szsTotal;
863 gone_els += elsTotal;
864 continue;
865 }
866 els = pp->elements();
Mark Salyzynfdabe722014-04-21 10:09:42 -0700867 bool gone = pp->pidGone();
Mark Salyzyn34facab2014-02-06 14:48:50 -0800868 if (gone && (els == 0)) {
869 // ToDo: garbage collection: move this statistical bucket
870 // from its current UID/PID to UID/? (races and
871 // wrap around are our achilles heel). Below is
872 // merely lipservice to catch PIDs that were still
873 // around when the stats were pruned to zero.
874 gone_szs += szsTotal;
875 gone_els += elsTotal;
876 continue;
877 }
878
Mark Salyzyne457b742014-02-19 17:18:31 -0800879 if (!first && (spaces > 0)) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800880 string.appendFormat("%*s", spaces, "");
881 }
882 spaces = 0;
883
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700884 intermediate = string.format(gone ? "%d/%d?" : "%d/%d", u, p);
885 string.appendFormat(first ? "\n%-12s" : "%-12s",
Mark Salyzyn34facab2014-02-06 14:48:50 -0800886 intermediate.string());
887 intermediate.clear();
888
889 oldLength = string.length();
890 string.appendFormat("%zu/%zu", szsTotal, elsTotal);
891 spaces += spaces_total + oldLength - string.length();
892
893 if (els == elsTotal) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800894 if (spaces < 0) {
895 spaces = 0;
896 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800897 string.appendFormat("%*s=", spaces, "");
898 spaces = -1;
899 } else if (els) {
900 oldLength = string.length();
Mark Salyzyne457b742014-02-19 17:18:31 -0800901 if (spaces < 0) {
902 spaces = 0;
903 }
Mark Salyzyn34facab2014-02-06 14:48:50 -0800904 string.appendFormat("%*s%zu/%zu", spaces, "",
905 pp->sizes(), els);
906 spaces -= string.length() - oldLength;
907 }
908 spaces += spaces_current;
909
910 first = !first;
911 }
912
913 if (gone_els) {
Mark Salyzyne457b742014-02-19 17:18:31 -0800914 if (!first && (spaces > 0)) {
Mark Salyzyn34facab2014-02-06 14:48:50 -0800915 string.appendFormat("%*s", spaces, "");
916 }
917
918 intermediate = string.format("%d/?", u);
Mark Salyzyn8e72c532014-03-26 10:46:39 -0700919 string.appendFormat(first ? "\n%-12s" : "%-12s",
Mark Salyzyn34facab2014-02-06 14:48:50 -0800920 intermediate.string());
921 intermediate.clear();
922
923 spaces = spaces_total + spaces_current;
924
925 oldLength = string.length();
926 string.appendFormat("%zu/%zu", gone_szs, gone_els);
927 spaces -= string.length() - oldLength;
928
929 first = !first;
930 }
931 }
932 }
933
Mark Salyzyndfa7a072014-02-11 12:29:31 -0800934 *buf = strdup(string.string());
Mark Salyzyn34facab2014-02-06 14:48:50 -0800935}
Mark Salyzyn4ba03872014-04-07 07:15:33 -0700936
937uid_t LogStatistics::pidToUid(pid_t pid) {
938 log_id_for_each(i) {
939 LidStatistics &l = id(i);
940 UidStatisticsCollection::iterator iu;
941 for (iu = l.begin(); iu != l.end(); ++iu) {
942 UidStatistics &u = *(*iu);
943 PidStatisticsCollection::iterator ip;
944 for (ip = u.begin(); ip != u.end(); ++ip) {
945 if ((*ip)->getPid() == pid) {
946 return u.getUid();
947 }
948 }
949 }
950 }
951 return getuid(); // associate this with the logger
952}