Home | History | Annotate | Download | only in trace_processor 
      1 /*
      2  * Copyright (C) 2018 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 <aio.h>
     18 #include <fcntl.h>
     19 #include <inttypes.h>
     20 #include <stdio.h>
     21 #include <sys/stat.h>
     22 #include <unistd.h>
     23 
     24 #include <functional>
     25 #include <iostream>
     26 #include <vector>
     27 
     28 #include "perfetto/base/build_config.h"
     29 #include "perfetto/base/logging.h"
     30 #include "perfetto/base/scoped_file.h"
     31 #include "perfetto/base/string_splitter.h"
     32 #include "perfetto/base/time.h"
     33 #include "perfetto/trace_processor/trace_processor.h"
     34 
     35 #if PERFETTO_BUILDFLAG(PERFETTO_OS_LINUX) ||   \
     36     PERFETTO_BUILDFLAG(PERFETTO_OS_ANDROID) || \
     37     PERFETTO_BUILDFLAG(PERFETTO_OS_MACOSX)
     38 #define PERFETTO_HAS_SIGNAL_H() 1
     39 #else
     40 #define PERFETTO_HAS_SIGNAL_H() 0
     41 #endif
     42 
     43 #if PERFETTO_BUILDFLAG(PERFETTO_STANDALONE_BUILD)
     44 #include <linenoise.h>
     45 #include <pwd.h>
     46 #include <sys/types.h>
     47 #include "perfetto_version.gen.h"
     48 #else
     49 #define PERFETTO_GET_GIT_REVISION() "unknown"
     50 #endif
     51 
     52 #if PERFETTO_HAS_SIGNAL_H()
     53 #include <signal.h>
     54 #endif
     55 
     56 namespace perfetto {
     57 namespace trace_processor {
     58 
     59 namespace {
     60 TraceProcessor* g_tp;
     61 
     62 #if PERFETTO_BUILDFLAG(PERFETTO_STANDALONE_BUILD)
     63 
     64 bool EnsureDir(const std::string& path) {
     65   return mkdir(path.c_str(), 0755) != -1 || errno == EEXIST;
     66 }
     67 
     68 bool EnsureFile(const std::string& path) {
     69   return base::OpenFile(path, O_RDONLY | O_CREAT, 0644).get() != -1;
     70 }
     71 
     72 std::string GetConfigPath() {
     73   const char* homedir = getenv("HOME");
     74   if (homedir == nullptr)
     75     homedir = getpwuid(getuid())->pw_dir;
     76   if (homedir == nullptr)
     77     return "";
     78   return std::string(homedir) + "/.config";
     79 }
     80 
     81 std::string GetPerfettoPath() {
     82   std::string config = GetConfigPath();
     83   if (config == "")
     84     return "";
     85   return config + "/perfetto";
     86 }
     87 
     88 std::string GetHistoryPath() {
     89   std::string perfetto = GetPerfettoPath();
     90   if (perfetto == "")
     91     return "";
     92   return perfetto + "/.trace_processor_shell_history";
     93 }
     94 
     95 void SetupLineEditor() {
     96   linenoiseSetMultiLine(true);
     97   linenoiseHistorySetMaxLen(1000);
     98 
     99   bool success = GetHistoryPath() != "";
    100   success = success && EnsureDir(GetConfigPath());
    101   success = success && EnsureDir(GetPerfettoPath());
    102   success = success && EnsureFile(GetHistoryPath());
    103   success = success && linenoiseHistoryLoad(GetHistoryPath().c_str()) != -1;
    104   if (!success) {
    105     PERFETTO_PLOG("Could not load history from %s", GetHistoryPath().c_str());
    106   }
    107 }
    108 
    109 void FreeLine(char* line) {
    110   linenoiseHistoryAdd(line);
    111   linenoiseHistorySave(GetHistoryPath().c_str());
    112   linenoiseFree(line);
    113 }
    114 
    115 char* GetLine(const char* prompt) {
    116   return linenoise(prompt);
    117 }
    118 
    119 #else
    120 
    121 void SetupLineEditor() {}
    122 
    123 void FreeLine(char* line) {
    124   delete[] line;
    125 }
    126 
    127 char* GetLine(const char* prompt) {
    128   printf("\r%80s\r%s", "", prompt);
    129   fflush(stdout);
    130   char* line = new char[1024];
    131   if (!fgets(line, 1024 - 1, stdin)) {
    132     FreeLine(line);
    133     return nullptr;
    134   }
    135   if (strlen(line) > 0)
    136     line[strlen(line) - 1] = 0;
    137   return line;
    138 }
    139 
    140 #endif
    141 
    142 bool PrintStats() {
    143   auto it = g_tp->ExecuteQuery(
    144       "SELECT name, idx, source, value from stats "
    145       "where severity = 'error' and value > 0");
    146 
    147   bool first = true;
    148   for (uint32_t rows = 0; it.Next(); rows++) {
    149     if (first) {
    150       fprintf(stderr, "Error stats for this trace:\n");
    151 
    152       for (uint32_t i = 0; i < it.ColumnCount(); i++)
    153         fprintf(stderr, "%40s ", it.GetColumName(i).c_str());
    154       fprintf(stderr, "\n");
    155 
    156       for (uint32_t i = 0; i < it.ColumnCount(); i++)
    157         fprintf(stderr, "%40s ", "----------------------------------------");
    158       fprintf(stderr, "\n");
    159 
    160       first = false;
    161     }
    162 
    163     for (uint32_t c = 0; c < it.ColumnCount(); c++) {
    164       auto value = it.Get(c);
    165       switch (value.type) {
    166         case SqlValue::Type::kNull:
    167           fprintf(stderr, "%-40.40s", "[NULL]");
    168           break;
    169         case SqlValue::Type::kDouble:
    170           fprintf(stderr, "%40f", value.double_value);
    171           break;
    172         case SqlValue::Type::kLong:
    173           fprintf(stderr, "%40" PRIi64, value.long_value);
    174           break;
    175         case SqlValue::Type::kString:
    176           fprintf(stderr, "%-40.40s", value.string_value);
    177           break;
    178       }
    179       fprintf(stderr, " ");
    180     }
    181     fprintf(stderr, "\n");
    182   }
    183 
    184   if (base::Optional<std::string> opt_error = it.GetLastError()) {
    185     PERFETTO_ELOG("Error while iterating stats %s", opt_error->c_str());
    186     return false;
    187   }
    188   return true;
    189 }
    190 
    191 int ExportTraceToDatabase(const std::string& output_name) {
    192   PERFETTO_CHECK(output_name.find("'") == std::string::npos);
    193   {
    194     base::ScopedFile fd(base::OpenFile(output_name, O_CREAT | O_RDWR, 0600));
    195     if (!fd) {
    196       PERFETTO_PLOG("Failed to create file: %s", output_name.c_str());
    197       return 1;
    198     }
    199     int res = ftruncate(fd.get(), 0);
    200     PERFETTO_CHECK(res == 0);
    201   }
    202 
    203   std::string attach_sql =
    204       "ATTACH DATABASE '" + output_name + "' AS perfetto_export";
    205   auto attach_it = g_tp->ExecuteQuery(attach_sql);
    206   bool attach_has_more = attach_it.Next();
    207   PERFETTO_DCHECK(!attach_has_more);
    208   if (base::Optional<std::string> opt_error = attach_it.GetLastError()) {
    209     PERFETTO_ELOG("SQLite error: %s", opt_error->c_str());
    210     return 1;
    211   }
    212 
    213   auto tables_it = g_tp->ExecuteQuery(
    214       "SELECT name FROM perfetto_tables UNION "
    215       "SELECT name FROM sqlite_master WHERE type='table'");
    216   for (uint32_t rows = 0; tables_it.Next(); rows++) {
    217     std::string table_name = tables_it.Get(0).string_value;
    218     PERFETTO_CHECK(table_name.find("'") == std::string::npos);
    219     std::string export_sql = "CREATE TABLE perfetto_export." + table_name +
    220                              " AS SELECT * FROM " + table_name;
    221 
    222     auto export_it = g_tp->ExecuteQuery(export_sql);
    223     bool export_has_more = export_it.Next();
    224     PERFETTO_DCHECK(!export_has_more);
    225     if (base::Optional<std::string> opt_error = export_it.GetLastError()) {
    226       PERFETTO_ELOG("SQLite error: %s", opt_error->c_str());
    227       return 1;
    228     }
    229   }
    230   if (base::Optional<std::string> opt_error = tables_it.GetLastError()) {
    231     PERFETTO_ELOG("SQLite error: %s", opt_error->c_str());
    232     return 1;
    233   }
    234 
    235   auto detach_it = g_tp->ExecuteQuery("DETACH DATABASE perfetto_export");
    236   bool detach_has_more = attach_it.Next();
    237   PERFETTO_DCHECK(!detach_has_more);
    238   if (base::Optional<std::string> opt_error = detach_it.GetLastError()) {
    239     PERFETTO_ELOG("SQLite error: %s", opt_error->c_str());
    240     return 1;
    241   }
    242   return 0;
    243 }
    244 
    245 int RunMetrics(const std::vector<std::string>& metric_names) {
    246   std::vector<uint8_t> metric_result;
    247   int res = g_tp->ComputeMetric(metric_names, &metric_result);
    248   if (res) {
    249     PERFETTO_ELOG("Error when computing metrics");
    250     return 1;
    251   }
    252   fwrite(metric_result.data(), sizeof(uint8_t), metric_result.size(), stdout);
    253   return 0;
    254 }
    255 
    256 void PrintQueryResultInteractively(TraceProcessor::Iterator* it,
    257                                    base::TimeNanos t_start) {
    258   base::TimeNanos t_end = t_start;
    259   for (uint32_t rows = 0; it->Next(); rows++) {
    260     if (rows % 32 == 0) {
    261       if (rows > 0) {
    262         fprintf(stderr, "...\nType 'q' to stop, Enter for more records: ");
    263         fflush(stderr);
    264         char input[32];
    265         if (!fgets(input, sizeof(input) - 1, stdin))
    266           exit(0);
    267         if (input[0] == 'q')
    268           break;
    269       } else {
    270         t_end = base::GetWallTimeNs();
    271       }
    272       for (uint32_t i = 0; i < it->ColumnCount(); i++)
    273         printf("%20s ", it->GetColumName(i).c_str());
    274       printf("\n");
    275 
    276       for (uint32_t i = 0; i < it->ColumnCount(); i++)
    277         printf("%20s ", "--------------------");
    278       printf("\n");
    279     }
    280 
    281     for (uint32_t c = 0; c < it->ColumnCount(); c++) {
    282       auto value = it->Get(c);
    283       switch (value.type) {
    284         case SqlValue::Type::kNull:
    285           printf("%-20.20s", "[NULL]");
    286           break;
    287         case SqlValue::Type::kDouble:
    288           printf("%20f", value.double_value);
    289           break;
    290         case SqlValue::Type::kLong:
    291           printf("%20" PRIi64, value.long_value);
    292           break;
    293         case SqlValue::Type::kString:
    294           printf("%-20.20s", value.string_value);
    295           break;
    296       }
    297       printf(" ");
    298     }
    299     printf("\n");
    300   }
    301 
    302   if (base::Optional<std::string> opt_error = it->GetLastError()) {
    303     PERFETTO_ELOG("SQLite error: %s", opt_error->c_str());
    304   }
    305   printf("\nQuery executed in %.3f ms\n\n", (t_end - t_start).count() / 1E6);
    306 }
    307 
    308 void PrintShellUsage() {
    309   PERFETTO_ELOG(
    310       "Available commands:\n"
    311       ".quit, .q    Exit the shell.\n"
    312       ".help        This text.\n"
    313       ".dump FILE   Export the trace as a sqlite database.\n");
    314 }
    315 
    316 int StartInteractiveShell() {
    317   SetupLineEditor();
    318 
    319   for (;;) {
    320     char* line = GetLine("> ");
    321     if (!line)
    322       break;
    323     if (strcmp(line, "") == 0)
    324       continue;
    325     if (line[0] == '.') {
    326       char command[32] = {};
    327       char arg[1024] = {};
    328       sscanf(line + 1, "%31s %1023s", command, arg);
    329       if (strcmp(command, "quit") == 0 || strcmp(command, "q") == 0) {
    330         break;
    331       } else if (strcmp(command, "help") == 0) {
    332         PrintShellUsage();
    333       } else if (strcmp(command, "dump") == 0 && strlen(arg)) {
    334         if (ExportTraceToDatabase(arg) != 0)
    335           PERFETTO_ELOG("Database export failed");
    336       } else {
    337         PrintShellUsage();
    338       }
    339       continue;
    340     }
    341 
    342     base::TimeNanos t_start = base::GetWallTimeNs();
    343     auto it = g_tp->ExecuteQuery(line);
    344     PrintQueryResultInteractively(&it, t_start);
    345 
    346     FreeLine(line);
    347   }
    348   return 0;
    349 }
    350 
    351 void PrintQueryResultAsCsv(TraceProcessor::Iterator* it, FILE* output) {
    352   for (uint32_t c = 0; c < it->ColumnCount(); c++) {
    353     if (c > 0)
    354       fprintf(output, ",");
    355     fprintf(output, "\"%s\"", it->GetColumName(c).c_str());
    356   }
    357   fprintf(output, "\n");
    358 
    359   for (uint32_t rows = 0; it->Next(); rows++) {
    360     for (uint32_t c = 0; c < it->ColumnCount(); c++) {
    361       if (c > 0)
    362         fprintf(output, ",");
    363 
    364       auto value = it->Get(c);
    365       switch (value.type) {
    366         case SqlValue::Type::kNull:
    367           fprintf(output, "\"%s\"", "[NULL]");
    368           break;
    369         case SqlValue::Type::kDouble:
    370           fprintf(output, "%f", value.double_value);
    371           break;
    372         case SqlValue::Type::kLong:
    373           fprintf(output, "%" PRIi64, value.long_value);
    374           break;
    375         case SqlValue::Type::kString:
    376           fprintf(output, "\"%s\"", value.string_value);
    377           break;
    378       }
    379     }
    380     fprintf(output, "\n");
    381   }
    382 }
    383 
    384 bool LoadQueries(FILE* input, std::vector<std::string>* output) {
    385   char buffer[4096];
    386   while (!feof(input) && !ferror(input)) {
    387     std::string sql_query;
    388     while (fgets(buffer, sizeof(buffer), input)) {
    389       if (strncmp(buffer, "\n", sizeof(buffer)) == 0)
    390         break;
    391       sql_query.append(buffer);
    392     }
    393     if (sql_query.back() == '\n')
    394       sql_query.resize(sql_query.size() - 1);
    395 
    396     // If we have a new line at the end of the file or an extra new line
    397     // somewhere in the file, we'll end up with an empty query which we should
    398     // just ignore.
    399     if (sql_query.empty())
    400       continue;
    401 
    402     output->push_back(sql_query);
    403   }
    404   if (ferror(input)) {
    405     PERFETTO_ELOG("Error reading query file");
    406     return false;
    407   }
    408   return true;
    409 }
    410 
    411 bool RunQueryAndPrintResult(const std::vector<std::string> queries,
    412                             FILE* output) {
    413   bool is_first_query = true;
    414   bool is_query_error = false;
    415   bool has_output = false;
    416   for (const auto& sql_query : queries) {
    417     // Add an extra newline separator between query results.
    418     if (!is_first_query)
    419       fprintf(output, "\n");
    420     is_first_query = false;
    421 
    422     PERFETTO_ILOG("Executing query: %s", sql_query.c_str());
    423 
    424     auto it = g_tp->ExecuteQuery(sql_query);
    425     if (base::Optional<std::string> opt_error = it.GetLastError()) {
    426       PERFETTO_ELOG("SQLite error: %s", opt_error->c_str());
    427       is_query_error = true;
    428       break;
    429     }
    430     if (it.ColumnCount() == 0) {
    431       bool it_has_more = it.Next();
    432       PERFETTO_DCHECK(!it_has_more);
    433       continue;
    434     }
    435 
    436     if (has_output) {
    437       PERFETTO_ELOG(
    438           "More than one query generated result rows. This is "
    439           "unsupported.");
    440       is_query_error = true;
    441       break;
    442     }
    443     PrintQueryResultAsCsv(&it, output);
    444     has_output = true;
    445   }
    446   return !is_query_error;
    447 }
    448 
    449 void PrintUsage(char** argv) {
    450   PERFETTO_ELOG(
    451       "Interactive trace processor shell.\n"
    452       "Usage: %s [OPTIONS] trace_file.pb\n\n"
    453       "Options:\n"
    454       " -d                   Enable virtual table debugging.\n"
    455       " -s FILE              Read and execute contents of file before "
    456       "launching an interactive shell.\n"
    457       " -q FILE              Read and execute an SQL query from a file.\n"
    458       " -e FILE              Export the trace into a SQLite database.\n"
    459       " --run-metrics x,y,z   Runs a comma separated list of metrics and "
    460       "prints the result as a TraceMetrics proto to stdout.\n",
    461       argv[0]);
    462 }
    463 
    464 int TraceProcessorMain(int argc, char** argv) {
    465   if (argc < 2) {
    466     PrintUsage(argv);
    467     return 1;
    468   }
    469   const char* trace_file_path = nullptr;
    470   const char* query_file_path = nullptr;
    471   const char* sqlite_file_path = nullptr;
    472   const char* metric_names = nullptr;
    473   bool launch_shell = true;
    474   for (int i = 1; i < argc; i++) {
    475     if (strcmp(argv[i], "-v") == 0 || strcmp(argv[i], "--version") == 0) {
    476       printf("%s\n", PERFETTO_GET_GIT_REVISION());
    477       exit(0);
    478     }
    479     if (strcmp(argv[i], "-d") == 0) {
    480       EnableSQLiteVtableDebugging();
    481       continue;
    482     }
    483     if (strcmp(argv[i], "-q") == 0 || strcmp(argv[i], "-s") == 0) {
    484       launch_shell = strcmp(argv[i], "-s") == 0;
    485       if (++i == argc) {
    486         PrintUsage(argv);
    487         return 1;
    488       }
    489       query_file_path = argv[i];
    490       continue;
    491     } else if (strcmp(argv[i], "-e") == 0) {
    492       if (++i == argc) {
    493         PrintUsage(argv);
    494         return 1;
    495       }
    496       sqlite_file_path = argv[i];
    497       continue;
    498     } else if (strcmp(argv[i], "--run-metrics") == 0) {
    499       if (++i == argc) {
    500         PrintUsage(argv);
    501         return 1;
    502       }
    503       metric_names = argv[i];
    504       continue;
    505     } else if (strcmp(argv[i], "-h") == 0 || strcmp(argv[i], "--help") == 0) {
    506       PrintUsage(argv);
    507       return 0;
    508     } else if (argv[i][0] == '-') {
    509       PERFETTO_ELOG("Unknown option: %s", argv[i]);
    510       return 1;
    511     }
    512     trace_file_path = argv[i];
    513   }
    514 
    515   if (trace_file_path == nullptr) {
    516     PrintUsage(argv);
    517     return 1;
    518   }
    519 
    520   // Load the trace file into the trace processor.
    521   Config config;
    522   std::unique_ptr<TraceProcessor> tp = TraceProcessor::CreateInstance(config);
    523   base::ScopedFile fd(base::OpenFile(trace_file_path, O_RDONLY));
    524   if (!fd) {
    525     PERFETTO_ELOG("Could not open trace file (path: %s)", trace_file_path);
    526     return 1;
    527   }
    528 
    529   // Load the trace in chunks using async IO. We create a simple pipeline where,
    530   // at each iteration, we parse the current chunk and asynchronously start
    531   // reading the next chunk.
    532 
    533   // 1MB chunk size seems the best tradeoff on a MacBook Pro 2013 - i7 2.8 GHz.
    534   constexpr size_t kChunkSize = 1024 * 1024;
    535   struct aiocb cb {};
    536   cb.aio_nbytes = kChunkSize;
    537   cb.aio_fildes = *fd;
    538 
    539   std::unique_ptr<uint8_t[]> aio_buf(new uint8_t[kChunkSize]);
    540 #if defined(MEMORY_SANITIZER)
    541   // Just initialize the memory to make the memory sanitizer happy as it
    542   // cannot track aio calls below.
    543   memset(aio_buf.get(), 0, kChunkSize);
    544 #endif
    545   cb.aio_buf = aio_buf.get();
    546 
    547   PERFETTO_CHECK(aio_read(&cb) == 0);
    548   struct aiocb* aio_list[1] = {&cb};
    549 
    550   uint64_t file_size = 0;
    551   auto t_load_start = base::GetWallTimeMs();
    552   for (int i = 0;; i++) {
    553     if (i % 128 == 0)
    554       fprintf(stderr, "\rLoading trace: %.2f MB\r", file_size / 1E6);
    555 
    556     // Block waiting for the pending read to complete.
    557     PERFETTO_CHECK(aio_suspend(aio_list, 1, nullptr) == 0);
    558     auto rsize = aio_return(&cb);
    559     if (rsize <= 0)
    560       break;
    561     file_size += static_cast<uint64_t>(rsize);
    562 
    563     // Take ownership of the completed buffer and enqueue a new async read
    564     // with a fresh buffer.
    565     std::unique_ptr<uint8_t[]> buf(std::move(aio_buf));
    566     aio_buf.reset(new uint8_t[kChunkSize]);
    567 #if defined(MEMORY_SANITIZER)
    568     // Just initialize the memory to make the memory sanitizer happy as it
    569     // cannot track aio calls below.
    570     memset(aio_buf.get(), 0, kChunkSize);
    571 #endif
    572     cb.aio_buf = aio_buf.get();
    573     cb.aio_offset += rsize;
    574     PERFETTO_CHECK(aio_read(&cb) == 0);
    575 
    576     // Parse the completed buffer while the async read is in-flight.
    577     tp->Parse(std::move(buf), static_cast<size_t>(rsize));
    578   }
    579   tp->NotifyEndOfFile();
    580   double t_load = (base::GetWallTimeMs() - t_load_start).count() / 1E3;
    581   double size_mb = file_size / 1E6;
    582   PERFETTO_ILOG("Trace loaded: %.2f MB (%.1f MB/s)", size_mb, size_mb / t_load);
    583   g_tp = tp.get();
    584 
    585 #if PERFETTO_HAS_SIGNAL_H()
    586   signal(SIGINT, [](int) { g_tp->InterruptQuery(); });
    587 #endif
    588 
    589   // Print out the stats to stderr for the trace.
    590   if (!PrintStats()) {
    591     return 1;
    592   }
    593 
    594   // First, see if we have some metrics to run. If we do, just run them and
    595   // return.
    596   if (metric_names) {
    597     std::vector<std::string> metrics;
    598     for (base::StringSplitter ss(metric_names, ','); ss.Next();) {
    599       metrics.emplace_back(ss.cur_token());
    600     }
    601     return RunMetrics(std::move(metrics));
    602   }
    603 
    604   // If we were given a query file, load contents
    605   std::vector<std::string> queries;
    606   if (query_file_path) {
    607     base::ScopedFstream file(fopen(query_file_path, "r"));
    608     if (!file) {
    609       PERFETTO_ELOG("Could not open query file (path: %s)", query_file_path);
    610       return 1;
    611     }
    612     if (!LoadQueries(file.get(), &queries)) {
    613       return 1;
    614     }
    615   }
    616 
    617   if (!RunQueryAndPrintResult(queries, stdout)) {
    618     return 1;
    619   }
    620 
    621   // After this we can dump the database and exit if needed.
    622   if (sqlite_file_path) {
    623     return ExportTraceToDatabase(sqlite_file_path);
    624   }
    625 
    626   // If we ran an automated query, exit.
    627   if (!launch_shell) {
    628     return 0;
    629   }
    630 
    631   // Otherwise start an interactive shell.
    632   return StartInteractiveShell();
    633 }
    634 
    635 }  // namespace
    636 
    637 }  // namespace trace_processor
    638 }  // namespace perfetto
    639 
    640 int main(int argc, char** argv) {
    641   return perfetto::trace_processor::TraceProcessorMain(argc, argv);
    642 }
    643