ANRdaemon/ANRdaemon.cpp

   1 /*
   2  * Copyright (c) 2015, The Android Open Source Project
   3  * All rights reserved.
   4  *
   5  * Redistribution and use in source and binary forms, with or without
   6  * modification, are permitted provided that the following conditions
   7  * are met:
   8  *   * Redistributions of source code must retain the above copyright
   9  *     notice, this list of conditions and the following disclaimer.
  10  *   * Redistributions in binary form must reproduce the above copyright
  11  *     notice, this list of conditions and the following disclaimer
  12  *     in the documentation and/or other materials provided with the
  13  *     distribution.
  14  *   * Neither the name of Google, Inc. nor the names of its contributors
  15  *     may be used to endorse or promote products derived from this
  16  *     software without specific prior written permission.
  17  *
  18  * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
  19  * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
  20  * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
  21  * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
  22  * COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
  23  * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING,
  24  * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS
  25  * OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED
  26  * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
  27  * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
  28  * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  29  * SUCH DAMAGE.
  30  */
  31
  32 #include <binder/IBinder.h>
  33 #include <binder/IServiceManager.h>
  34 #include <binder/Parcel.h>
  35
  36 #include <ctime>
  37 #include <cutils/properties.h>
  38 #include <signal.h>
  39 #include <stdbool.h>
  40 #include <stdio.h>
  41 #include <stdlib.h>
  42 #include <string.h>
  43
  44 #include <sys/resource.h>
  45 #include <sys/stat.h>
  46 #include <sys/time.h>
  47 #include <sys/types.h>
  48 #include <unistd.h>
  49
  50 #include <utils/Log.h>
  51 #include <utils/String8.h>
  52 #include <utils/Trace.h>
  53 #include <zlib.h>
  54
  55 using namespace android;
  56
  57 #define CHECK_PERIOD 1  // in sec
  58 #define TRACING_CHECK_PERIOD 500000 // in micro sec
  59 #define MIN_BUFFER_SIZE 4
  60 #define MIN_BUFFER_SIZE_STR "4"
  61 #define MAX_BUFFER_SIZE 128
  62 #define MAX_BUFFER_SIZE_STR "128"
  63 #define CPU_STAT_ENTRIES 7 // number of cpu stat entries
  64
  65 #ifdef LOG_TAG
  66 #undef LOG_TAG
  67 #endif
  68
  69 #define LOG_TAG "anrdaemon"
  70
  71 typedef struct cpu_stat {
  72     unsigned long utime, ntime, stime, itime;
  73     unsigned long iowtime, irqtime, sirqtime, steal;
  74     unsigned long total;
  75 } cpu_stat_t;
  76
  77 /* Make the logging on/off threshold equal to 95% cpu usage. */
  78 static int idle_threshold = 5;
  79
  80 static bool quit = false;
  81 static bool suspend= false;
  82 static bool err = false;
  83 static char err_msg[100];
  84 static bool tracing = false;
  85
  86 static const char *buf_size_kb = "16";
  87 static uint64_t tag = 0;
  88 static const char* apps = "";
  89
  90 static cpu_stat_t new_cpu;
  91 static cpu_stat_t old_cpu;
  92 static Vector<String16> targets;
  93
  94 /* Log certain kernel activity when enabled */
  95 static bool log_sched = false;
  96 static bool log_stack = false;
  97 static bool log_irq   = false;
  98 static bool log_sync  = false;
  99 static bool log_workq = false;
 100
 101 /* Paths for debugfs controls*/
 102 static const char* dfs_trace_output_path =
 103     "/d/tracing/trace";
 104 static const char* dfs_irq_path =
 105     "/d/tracing/events/irq/enable";
 106 static const char* dfs_sync_path =
 107     "/d/tracing/events/sync/enable";
 108 static const char* dfs_workq_path =
 109     "/d/tracing/events/workqueue/enable";
 110 static const char* dfs_stack_path =
 111     "/d/tracing/options/stacktrace";
 112 static const char* dfs_sched_switch_path =
 113     "/d/tracing/events/sched/sched_switch/enable";
 114 static const char* dfs_sched_wakeup_path =
 115     "/d/tracing/events/sched/sched_wakeup/enable";
 116 static const char* dfs_control_path =
 117     "/d/tracing/tracing_on";
 118 static const char* dfs_buffer_size_path =
 119     "/d/tracing/buffer_size_kb";
 120 static const char* dfs_tags_property = "debug.atrace.tags.enableflags";
 121 static const char* dfs_apps_property = "debug.atrace.app_cmdlines";
 122
 123 /*
 124  * Read accumulated cpu data from /proc/stat
 125  */
 126 static void get_cpu_stat(cpu_stat_t *cpu) {
 127     FILE *fp = NULL;
 128     const char *params = "cpu  %lu %lu %lu %lu %lu %lu %lu %*d %*d %*d\n";
 129
 130     if ((fp = fopen("/proc/stat", "r")) == NULL) {
 131         err = true;
 132         sprintf(err_msg, "can't read from /proc/stat with errno %d", errno);
 133     } else {
 134         if (fscanf(fp, params, &cpu->utime, &cpu->ntime,
 135                 &cpu->stime, &cpu->itime, &cpu->iowtime, &cpu->irqtime,
 136                 &cpu->sirqtime) != CPU_STAT_ENTRIES) {
 137             /*
 138              * If failed in getting status, new_cpu won't be updated and
 139              * is_heavy_loaded() will return false.
 140              */
 141             ALOGE("Error in getting cpu status. Skipping this check.");
 142             return;
 143         }
 144
 145         cpu->total = cpu->utime + cpu->ntime + cpu->stime + cpu->itime
 146             + cpu->iowtime + cpu->irqtime + cpu->sirqtime;
 147
 148         fclose(fp);
 149     }
 150 }
 151
 152 /*
 153  * Calculate cpu usage in the past interval.
 154  * If tracing is on, increase the idle threshold by 1% so that we do not
 155  * turn on and off tracing frequently whe the cpu load is right close to
 156  * threshold.
 157  */
 158 static bool is_heavy_load(void) {
 159     unsigned long diff_idle, diff_total;
 160     int threshold = idle_threshold + (tracing?1:0);
 161     get_cpu_stat(&new_cpu);
 162     diff_idle = new_cpu.itime - old_cpu.itime;
 163     diff_total = new_cpu.total - old_cpu.total;
 164     old_cpu = new_cpu;
 165     return (diff_idle * 100 < diff_total * threshold);
 166 }
 167
 168 /*
 169  * Force the userland processes to refresh their property for logging.
 170  */
 171 static void dfs_poke_binder(Vector<String16> services) {
 172     sp<IServiceManager> sm = defaultServiceManager();
 173     services = sm->listServices();
 174     for (size_t i = 0; i < services.size(); i++) {
 175         sp<IBinder> obj = sm->checkService(services[i]);
 176         if (obj != NULL) {
 177             Parcel data;
 178             obj->transact(IBinder::SYSPROPS_TRANSACTION, data, NULL, 0);
 179         }
 180     }
 181 }
 182
 183 /*
 184  * Enable/disable a debugfs property by writing 0/1 to its path.
 185  */
 186 static int dfs_enable(bool enable, const char* path) {
 187     int fd = open(path, O_WRONLY);
 188     if (fd == -1) {
 189         err = true;
 190         sprintf(err_msg, "Can't open %s. Error: %d", path, errno);
 191         return -1;
 192     }
 193     const char* control = (enable?"1":"0");
 194     ssize_t len = strlen(control);
 195     int max_try = 10; // Fail if write was interrupted for 10 times
 196     while (write(fd, control, len) != len) {
 197         if (errno == EINTR && max_try-- > 0)
 198             continue;
 199
 200         err = true;
 201         sprintf(err_msg, "Error %d in writing to %s.", errno, path);
 202     }
 203     close(fd);
 204     return (err?-1:0);
 205 }
 206
 207 /*
 208  * Set the userland tracing properties.
 209  */
 210 static void dfs_set_property(uint64_t mtag, const char* mapp, bool enable) {
 211     char buf[64];
 212     snprintf(buf, 64, "%#" PRIx64, mtag);
 213     if (property_set(dfs_tags_property, buf) < 0) {
 214         err = true;
 215         sprintf(err_msg, "Failed to set debug tags system properties.");
 216     }
 217
 218     if (strlen(mapp) > 0
 219             && property_set(dfs_apps_property, mapp) < 0) {
 220         err = true;
 221         sprintf(err_msg, "Failed to set debug applications.");
 222     }
 223
 224     if (log_sched) {
 225         dfs_enable(enable, dfs_sched_switch_path);
 226         dfs_enable(enable, dfs_sched_wakeup_path);
 227     }
 228     if (log_stack) {
 229         dfs_enable(enable, dfs_stack_path);
 230     }
 231     if (log_irq) {
 232         dfs_enable(enable, dfs_irq_path);
 233     }
 234     if (log_sync) {
 235         dfs_enable(enable, dfs_sync_path);
 236     }
 237     if (log_workq) {
 238         dfs_enable(enable, dfs_workq_path);
 239     }
 240 }
 241
 242 /*
 243  * Start logging when cpu usage is high. Meanwhile, moniter the cpu usage and
 244  * stop logging when it drops down.
 245  */
 246 static void start_tracing(void) {
 247     ALOGD("High cpu usage, start logging.");
 248
 249     dfs_set_property(tag, apps, true);
 250     dfs_poke_binder(targets);
 251
 252     if (dfs_enable(true, dfs_control_path) != 0) {
 253         ALOGE("Failed to start tracing.");
 254         return;
 255     }
 256     tracing = true;
 257
 258     /* Stop logging when cpu usage drops or the daemon is suspended.*/
 259     do {
 260         usleep(TRACING_CHECK_PERIOD);
 261     } while (!suspend && is_heavy_load());
 262
 263     if (dfs_enable(false, dfs_control_path) != 0) {
 264         ALOGE("Failed to stop tracing.");
 265     }
 266
 267     dfs_set_property(0, "", false);
 268     dfs_poke_binder(targets);
 269
 270     ALOGD("Usage back to low, stop logging.");
 271     tracing = false;
 272 }
 273
 274 /*
 275  * Set the tracing log buffer size.
 276  * Note the actual buffer size will be buf_size_kb * number of cores.
 277  * E.g. for dory, the total buffer size is buf_size_kb * 4.
 278  */
 279 static int set_tracing_buffer_size(void) {
 280     int fd = open(dfs_buffer_size_path, O_WRONLY);
 281     if (fd == -1) {
 282         err = true;
 283         sprintf(err_msg, "Can't open atrace buffer size file under /d/tracing.");
 284         return -1;
 285     }
 286     ssize_t len = strlen(buf_size_kb);
 287     if (write(fd, buf_size_kb, len) != len) {
 288         err = true;
 289         sprintf(err_msg, "Error in writing to atrace buffer size file.");
 290     }
 291     close(fd);
 292     return (err?-1:0);
 293
 294 }
 295
 296 /*
 297  * Main loop to moniter the cpu usage and decided whether to start logging.
 298  */
 299 static void start(void) {
 300     if ((set_tracing_buffer_size()) != 0)
 301         return;
 302     get_cpu_stat(&old_cpu);
 303     sleep(CHECK_PERIOD);
 304
 305     while (!quit && !err) {
 306         if (!suspend && is_heavy_load()) {
 307             /*
 308              * Increase process priority to make sure we can stop logging when
 309              * necessary and do not overwrite the buffer
 310              */
 311             setpriority(PRIO_PROCESS, 0, -20);
 312             start_tracing();
 313             setpriority(PRIO_PROCESS, 0, 0);
 314         }
 315         sleep(CHECK_PERIOD);
 316     }
 317     return;
 318 }
 319
 320 /*
 321  * Dump the log in a compressed format for systrace to visualize.
 322  */
 323 static void dump_trace()
 324 {
 325     int remain_attempts = 5;
 326     suspend = true;
 327     while (tracing) {
 328         ALOGI("Waiting logging to stop.");
 329         usleep(TRACING_CHECK_PERIOD);
 330         remain_attempts--;
 331         if (remain_attempts == 0) {
 332             ALOGE("Can't stop logging after 5 attempts. Dump aborted.");
 333             return;
 334         }
 335     }
 336
 337     /*
 338      * Create a dump file "dump_of_anrdaemon.<current_time>" under /data/anr/
 339      */
 340     time_t now = time(0);
 341     struct tm  tstruct;
 342     char time_buf[80];
 343     char path_buf[200];
 344     const char* header = " done\nTRACE:\n";
 345     ssize_t header_len = strlen(header);
 346     tstruct = *localtime(&now);
 347     strftime(time_buf, sizeof(time_buf), "%Y-%m-%d.%X", &tstruct);
 348     sprintf(path_buf, "/data/anr/dump_of_anrdaemon.%s", time_buf);
 349     int output_fd = creat(path_buf, S_IRWXU);
 350     if (output_fd == -1) {
 351         ALOGE("Failed to create %s. Dump aborted.", path_buf);
 352         return;
 353     }
 354
 355     if (write(output_fd, header, strlen(header)) != header_len) {
 356         ALOGE("Failed to write the header.");
 357         close(output_fd);
 358         return;
 359     }
 360
 361     int trace_fd = open(dfs_trace_output_path, O_RDWR);
 362     if (trace_fd == -1) {
 363         ALOGE("Failed to open %s. Dump aborted.", dfs_trace_output_path);
 364         close(output_fd);
 365         return;
 366     }
 367
 368     z_stream zs;
 369     uint8_t *in, *out;
 370     int result, flush;
 371
 372     memset(&zs, 0, sizeof(zs));
 373     result = deflateInit(&zs, Z_DEFAULT_COMPRESSION);
 374     if (result != Z_OK) {
 375         ALOGE("error initializing zlib: %d\n", result);
 376         close(trace_fd);
 377         close(output_fd);
 378         return;
 379     }
 380
 381     const size_t bufSize = 64*1024;
 382     in = (uint8_t*)malloc(bufSize);
 383     out = (uint8_t*)malloc(bufSize);
 384     flush = Z_NO_FLUSH;
 385
 386     zs.next_out = out;
 387     zs.avail_out = bufSize;
 388
 389     do {
 390         if (zs.avail_in == 0) {
 391             result = read(trace_fd, in, bufSize);
 392             if (result < 0) {
 393                 ALOGE("error reading trace: %s", strerror(errno));
 394                 result = Z_STREAM_END;
 395                 break;
 396             } else if (result == 0) {
 397                 flush = Z_FINISH;
 398             } else {
 399                 zs.next_in = in;
 400                 zs.avail_in = result;
 401             }
 402         }
 403
 404         if (zs.avail_out == 0) {
 405             result = write(output_fd, out, bufSize);
 406             if ((size_t)result < bufSize) {
 407                 ALOGE("error writing deflated trace: %s", strerror(errno));
 408                 result = Z_STREAM_END;
 409                 zs.avail_out = bufSize;
 410                 break;
 411             }
 412             zs.next_out = out;
 413             zs.avail_out = bufSize;
 414         }
 415
 416     } while ((result = deflate(&zs, flush)) == Z_OK);
 417
 418     if (result != Z_STREAM_END) {
 419         ALOGE("error deflating trace: %s\n", zs.msg);
 420     }
 421
 422     if (zs.avail_out < bufSize) {
 423         size_t bytes = bufSize - zs.avail_out;
 424         result = write(output_fd, out, bytes);
 425         if ((size_t)result < bytes) {
 426             ALOGE("error writing deflated trace: %s", strerror(errno));
 427         }
 428     }
 429
 430     result = deflateEnd(&zs);
 431     if (result != Z_OK) {
 432         ALOGE("error cleaning up zlib: %d\n", result);
 433     }
 434
 435     free(in);
 436     free(out);
 437
 438     close(trace_fd);
 439     close(output_fd);
 440
 441     suspend = false;
 442     ALOGI("Finished dump. Output file stored at: %s", path_buf);
 443 }
 444
 445 static void handle_signal(int signo)
 446 {
 447     switch (signo) {
 448         case SIGQUIT:
 449             suspend = true;
 450             quit = true;
 451             break;
 452         case SIGSTOP:
 453             suspend = true;
 454             break;
 455         case SIGCONT:
 456             suspend = false;
 457             break;
 458         case SIGUSR1:
 459             dump_trace();
 460     }
 461 }
 462
 463 /*
 464  * Set the signal handler:
 465  * SIGQUIT: Reset debugfs and tracing property and terminate the daemon.
 466  * SIGSTOP: Stop logging and suspend the daemon.
 467  * SIGCONT: Resume the daemon as normal.
 468  * SIGUSR1: Dump the logging to a compressed format for systrace to visualize.
 469  */
 470 static void register_sighandler(void)
 471 {
 472     struct sigaction sa;
 473     sigset_t block_mask;
 474
 475     sigemptyset(&block_mask);
 476     sigaddset (&block_mask, SIGQUIT);
 477     sigaddset (&block_mask, SIGSTOP);
 478     sigaddset (&block_mask, SIGCONT);
 479     sigaddset (&block_mask, SIGUSR1);
 480
 481     sa.sa_flags = 0;
 482     sa.sa_mask = block_mask;
 483     sa.sa_handler = handle_signal;
 484     sigaction(SIGQUIT, &sa, NULL);
 485     sigaction(SIGSTOP, &sa, NULL);
 486     sigaction(SIGCONT, &sa, NULL);
 487     sigaction(SIGUSR1, &sa, NULL);
 488 }
 489
 490 static void show_help(void) {
 491
 492     fprintf(stderr, "usage: ANRdaemon [options] [categoris...]\n");
 493     fprintf(stdout, "Options includes:\n"
 494                     "   -a appname  enable app-level tracing for a comma "
 495                        "separated list of cmdlines\n"
 496                     "   -t N        cpu threshold for logging to start "
 497                         "(min = 50, max = 100, default = 95)\n"
 498                     "   -s N        use a trace buffer size of N KB "
 499                         "default to 16KB\n"
 500                     "   -h          show helps\n");
 501     fprintf(stdout, "Categoris includes:\n"
 502                     "   am         - activity manager\n"
 503                     "   sm         - sync manager\n"
 504                     "   input      - input\n"
 505                     "   app        - application\n"
 506                     "   dalvik     - dalvik VM\n"
 507                     "   irq        - kernel irq events\n"
 508                     "   sched      - kernel scheduler activity\n"
 509                     "   stack      - kernel stack\n"
 510                     "   sync       - kernel sync activity\n"
 511                     "   workq      - kernel work queues\n");
 512     fprintf(stdout, "Control includes:\n"
 513                     "   SIGQUIT: terminate the process\n"
 514                     "   SIGSTOP: suspend all function of the daemon\n"
 515                     "   SIGCONT: resume the normal function\n"
 516                     "   SIGUSR1: dump the current logging in a compressed form\n");
 517     exit(0);
 518 }
 519
 520 static int get_options(int argc, char *argv[]) {
 521     int opt = 0;
 522     int threshold;
 523     while ((opt = getopt(argc, argv, "a:s:t:h")) >= 0) {
 524         switch(opt) {
 525             case 'a':
 526                 apps = optarg;
 527                 break;
 528             case 's':
 529                 if (atoi(optarg) > MAX_BUFFER_SIZE)
 530                     buf_size_kb = MAX_BUFFER_SIZE_STR;
 531                 else if (atoi(optarg) < MIN_BUFFER_SIZE)
 532                     buf_size_kb = MIN_BUFFER_SIZE_STR;
 533                 else
 534                     buf_size_kb = optarg;
 535                 break;
 536             case 't':
 537                 threshold = atoi(optarg);
 538                 if (threshold > 100 || threshold < 50) {
 539                     fprintf(stderr, "logging threshold should be 50-100\n");
 540                     return 1;
 541                 }
 542                 idle_threshold = 100 - threshold;
 543                 break;
 544             case 'h':
 545                 show_help();
 546                 break;
 547             default:
 548                 fprintf(stderr, "Error in getting options.\n"
 549                         "run \"%s -h\" for usage.\n", argv[0]);
 550                 return 1;
 551         }
 552     }
 553
 554     for (int i = optind; i < argc; i++) {
 555         if (strcmp(argv[i], "am") == 0) {
 556             tag |= ATRACE_TAG_ACTIVITY_MANAGER;
 557         } else if (strcmp(argv[i], "input") == 0) {
 558             tag |= ATRACE_TAG_INPUT;
 559         } else if (strcmp(argv[i], "sm") == 0) {
 560             tag |= ATRACE_TAG_SYNC_MANAGER;
 561         } else if (strcmp(argv[i], "app") == 0) {
 562             tag |= ATRACE_TAG_APP;
 563         } else if (strcmp(argv[i], "dalvik") == 0) {
 564             tag |= ATRACE_TAG_DALVIK;
 565         } else if (strcmp(argv[i], "sched") == 0) {
 566             log_sched = true;
 567         } else if (strcmp(argv[i], "stack") == 0) {
 568             log_stack = true;
 569         } else if (strcmp(argv[i], "workq") == 0) {
 570             log_workq = true;
 571         } else if (strcmp(argv[i], "irq") == 0) {
 572             log_irq = true;
 573         } else if (strcmp(argv[i], "sync") == 0) {
 574             log_sync = true;
 575         } else {
 576             fprintf(stderr, "invalid category: %s\n"
 577                     "run \"%s -h\" for usage.\n", argv[i], argv[0]);
 578             return 1;
 579         }
 580     }
 581
 582     bool kernel_log = log_sched || log_stack || log_workq || log_irq || log_sync;
 583     bool app_log = (tag == 0);
 584
 585     /*
 586      * There are ~80 services. Too expensive to poke all of them. Just include
 587      * service that may help high CPU ANR analysis.
 588      */
 589     if (app_log) {
 590        targets.push_back(String16("activity"));
 591        targets.push_back(String16("alarm"));
 592        targets.push_back(String16("appops"));
 593        targets.push_back(String16("cpuinfo"));
 594        targets.push_back(String16("meminfo"));
 595        targets.push_back(String16("procstats"));
 596        targets.push_back(String16("input"));
 597        targets.push_back(String16("lancherapps"));
 598        targets.push_back(String16("bluetooth_manager"));
 599        targets.push_back(String16("SurfaceFlinger"));
 600        targets.push_back(String16("ClockworkProxyNativeService"));
 601     }
 602     if (!kernel_log && !app_log) {
 603         tag |= ATRACE_TAG_ACTIVITY_MANAGER;
 604         targets.push_back(String16("activity"));
 605     }
 606
 607     return 0;
 608 }
 609
 610 int main(int argc, char *argv[])
 611 {
 612     if(get_options(argc, argv) != 0)
 613         return 1;
 614
 615     if (daemon(0, 0) != 0)
 616         return 1;
 617
 618     register_sighandler();
 619
 620     /* Clear any the trace log file by overwrite it with a new file */
 621     int fd = creat(dfs_trace_output_path, 0);
 622     if (fd == -1) {
 623         ALOGE("Faield to open and cleaup previous log");
 624         return 1;
 625     }
 626     close(fd);
 627
 628     ALOGI("ANRdaemon starting");
 629     start();
 630
 631     if (err)
 632         ALOGE("ANRdaemon stopped due to Error: %s", err_msg);
 633
 634     ALOGI("ANRdaemon terminated.");
 635
 636     return (err?1:0);
 637 }