perf sched: Show start of latency as well

The 'perf sched latency' tool is really useful at showing worst-case
latencies that task encountered since wakeup. However it shows only the
end of the latency. Often times the start of a latency is interesting as
it can show what else was going on at the time to cause the latency. I
certainly myself spending a lot of time backtracking to the start of the
latency in "perf sched script" which wastes a lot of time.

This patch therefore adds a new column "Max delay start". Considering
this, also rename "Maximum delay at" to "Max delay end" as its easier to
understand.

Example of the new output:

  ----------------------------------------------------------------------------------------------------------------------------------
   Task                  | Runtime ms  | Switches | Avg delay ms  | Max delay ms   | Max delay start         | Max delay end       |
  ----------------------------------------------------------------------------------------------------------------------------------
   MediaScannerSer:11936 |  651.296 ms |    67978 | avg: 0.113 ms | max: 77.250 ms | max start: 477.691360 s | max end: 477.768610 s
   audio@2.0-servi:(3)   |    0.000 ms |     3440 | avg: 0.034 ms | max: 72.267 ms | max start: 477.697051 s | max end: 477.769318 s
   AudioOut_1D:8112      |    0.000 ms |     2588 | avg: 0.083 ms | max: 64.020 ms | max start: 477.710740 s | max end: 477.774760 s
   Time-limited te:14973 | 7966.090 ms |    24807 | avg: 0.073 ms | max: 15.563 ms | max start: 477.162746 s | max end: 477.178309 s
   surfaceflinger:8049   |    9.680 ms |      603 | avg: 0.063 ms | max: 13.275 ms | max start: 476.931791 s | max end: 476.945067 s
   HeapTaskDaemon:(3)    | 1588.830 ms |     7040 | avg: 0.065 ms | max:  6.880 ms | max start: 473.666043 s | max end: 473.672922 s
   mount-passthrou:(3)   | 1370.809 ms |    68904 | avg: 0.011 ms | max:  6.524 ms | max start: 478.090630 s | max end: 478.097154 s
   ReferenceQueueD:(3)   |   11.794 ms |     1725 | avg: 0.014 ms | max:  6.521 ms | max start: 476.119782 s | max end: 476.126303 s
   writer:14077          |   18.410 ms |     1427 | avg: 0.036 ms | max:  6.131 ms | max start: 474.169675 s | max end: 474.175805 s

Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
Acked-by: Namhyung Kim <namhyung@kernel.org>
Link: https://lore.kernel.org/r/20200925235634.4089867-1-joel@joelfernandes.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index e6fc297..0e16f9d 100644 (file)
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -130,7 +130,8 @@ struct work_atoms {
        struct thread           *thread;
        struct rb_node          node;
        u64                     max_lat;
-       u64                     max_lat_at;
+       u64                     max_lat_start;
+       u64                     max_lat_end;
        u64                     total_lat;
        u64                     nb_atoms;
        u64                     total_runtime;
@@ -1096,7 +1097,8 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
        atoms->total_lat += delta;
        if (delta > atoms->max_lat) {
                atoms->max_lat = delta;
-               atoms->max_lat_at = timestamp;
+               atoms->max_lat_start = atom->wake_up_time;
+               atoms->max_lat_end = timestamp;
        }
        atoms->nb_atoms++;
 }
@@ -1322,7 +1324,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
        int i;
        int ret;
        u64 avg;
-       char max_lat_at[32];
+       char max_lat_start[32], max_lat_end[32];
 
        if (!work_list->nb_atoms)
                return;
@@ -1344,13 +1346,14 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
                printf(" ");
 
        avg = work_list->total_lat / work_list->nb_atoms;
-       timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
+       timestamp__scnprintf_usec(work_list->max_lat_start, max_lat_start, sizeof(max_lat_start));
+       timestamp__scnprintf_usec(work_list->max_lat_end, max_lat_end, sizeof(max_lat_end));
 
-       printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13s s\n",
+       printf("|%11.3f ms |%9" PRIu64 " | avg:%8.3f ms | max:%8.3f ms | max start: %12s s | max end: %12s s\n",
              (double)work_list->total_runtime / NSEC_PER_MSEC,
                 work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
                 (double)work_list->max_lat / NSEC_PER_MSEC,
-                max_lat_at);
+                max_lat_start, max_lat_end);
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
@@ -3137,7 +3140,8 @@ static void __merge_work_atoms(struct rb_root_cached *root, struct work_atoms *d
                        list_splice(&data->work_list, &this->work_list);
                        if (this->max_lat < data->max_lat) {
                                this->max_lat = data->max_lat;
-                               this->max_lat_at = data->max_lat_at;
+                               this->max_lat_start = data->max_lat_start;
+                               this->max_lat_end = data->max_lat_end;
                        }
                        zfree(&data);
                        return;
@@ -3176,9 +3180,9 @@ static int perf_sched__lat(struct perf_sched *sched)
        perf_sched__merge_lat(sched);
        perf_sched__sort_lat(sched);
 
-       printf("\n -----------------------------------------------------------------------------------------------------------------\n");
-       printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |\n");
-       printf(" -----------------------------------------------------------------------------------------------------------------\n");
+       printf("\n -------------------------------------------------------------------------------------------------------------------------------------------\n");
+       printf("  Task                  |   Runtime ms  | Switches | Avg delay ms    | Max delay ms    | Max delay start           | Max delay end          |\n");
+       printf(" -------------------------------------------------------------------------------------------------------------------------------------------\n");
 
        next = rb_first_cached(&sched->sorted_atom_root);