uftrace replay set time range fail

[tbar-hz]

I want to use parameter "-r" or "--time-range" to get some information in specify range time. But the result still show all the record information.

For example, there are the following trace reslut:

[root@localhost call_trace]# /usr/local/uftrace/bin/uftrace replay -f time,delta,duration,addr,tid
# DURATION     TID      ADDRESS        TIMESTAMP      TIMEDELTA   FUNCTION
            [ 19492]       400f89  1036490.242226865            | b_test() {
   1.000  s [ 19492]        30d42  1036490.242231943   5.078 us |   /* linux:schedule */
   1.022 us [ 19492]       400d80  1036491.242344771   1.000  s |   time();
   1.000  s [ 19492]        30d42  1036491.242354119   9.348 us |   /* linux:schedule */
            [ 19492]       400cb0  1036492.242859732   1.000  s |   sleep() {
   1.000  s [ 19492]        30d42  1036492.242865585   5.853 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036493.242994780   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036493.242996597   1.817 us |   sleep() {
   1.001  s [ 19492]        30d42  1036493.242999849   3.252 us |     /* linux:schedule */
   1.001  s [ 19492]       400cb0  1036494.244009497   1.001  s |   } /* sleep */
            [ 19492]       400cb0  1036494.244011290   1.793 us |   sleep() {
   1.000  s [ 19492]        30d42  1036494.244012806   1.516 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036495.244885248   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036495.244887323   2.075 us |   sleep() {
   1.000  s [ 19492]        30d42  1036495.244888664   1.341 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036496.245074506   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036496.245076563   2.057 us |   sleep() {
   1.000  s [ 19492]        30d42  1036496.245079586   3.023 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036497.245465124   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036497.245470655   5.531 us |   sleep() {
   1.000  s [ 19492]        30d42  1036497.245474823   4.168 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036498.246303646   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036498.246308479   4.833 us |   sleep() {
   1.000  s [ 19492]        30d42  1036498.246313789   5.310 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036499.246946556   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036499.246952587   6.031 us |   sleep() {
   1.000  s [ 19492]        30d42  1036499.246959548   6.961 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036500.247129402   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036500.247134237   4.835 us |   sleep() {
   1.003  s [ 19492]        30d42  1036500.247140129   5.892 us |     /* linux:schedule */
   1.003  s [ 19492]       400cb0  1036501.250391833   1.003  s |   } /* sleep */
   3.467 us [ 19492]       400c80  1036501.250395888   4.055 us |   std::operator<<();
            [ 19492]       400d20  1036501.250399777   3.889 us |   std::basic_ostream::operator<<() {
  10.227 us [ 19492]       400d40  1036501.250400067   0.290 us |     std::endl();
  10.742 us [ 19492]       400d20  1036501.250410519  10.452 us |   } /* std::basic_ostream::operator<< */
            [ 19492]               1036501.250575550 165.031 us |   /* linux:task-exit */

uftrace stopped tracing with remaining functions
================================================
task: 19492
[0] b_test

Then, use '-r' to specify a time range, but the result as same as filter before.

[root@localhost call_trace]# /usr/local/uftrace/bin/uftrace replay -r 1036493.242996597~1036498.246303646 -f time,delta,duration,addr,tid
Usage: --time-range cannot be used with --time-filter
# DURATION     TID      ADDRESS        TIMESTAMP      TIMEDELTA   FUNCTION
            [ 19492]       400f89  1036490.242226865            | b_test() {
   1.000  s [ 19492]        30d42  1036490.242231943   5.078 us |   /* linux:schedule */
   1.022 us [ 19492]       400d80  1036491.242344771   1.000  s |   time();
   1.000  s [ 19492]        30d42  1036491.242354119   9.348 us |   /* linux:schedule */
            [ 19492]       400cb0  1036492.242859732   1.000  s |   sleep() {
   1.000  s [ 19492]        30d42  1036492.242865585   5.853 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036493.242994780   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036493.242996597   1.817 us |   sleep() {
   1.001  s [ 19492]        30d42  1036493.242999849   3.252 us |     /* linux:schedule */
   1.001  s [ 19492]       400cb0  1036494.244009497   1.001  s |   } /* sleep */
            [ 19492]       400cb0  1036494.244011290   1.793 us |   sleep() {
   1.000  s [ 19492]        30d42  1036494.244012806   1.516 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036495.244885248   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036495.244887323   2.075 us |   sleep() {
   1.000  s [ 19492]        30d42  1036495.244888664   1.341 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036496.245074506   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036496.245076563   2.057 us |   sleep() {
   1.000  s [ 19492]        30d42  1036496.245079586   3.023 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036497.245465124   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036497.245470655   5.531 us |   sleep() {
   1.000  s [ 19492]        30d42  1036497.245474823   4.168 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036498.246303646   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036498.246308479   4.833 us |   sleep() {
   1.000  s [ 19492]        30d42  1036498.246313789   5.310 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036499.246946556   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036499.246952587   6.031 us |   sleep() **{**
   1.000  s [ 19492]        30d42  1036499.246959548   6.961 us |     /* linux:schedule */
   1.000  s [ 19492]       400cb0  1036500.247129402   1.000  s |   } /* sleep */
            [ 19492]       400cb0  1036500.247134237   4.835 us |   sleep() {
   1.003  s [ 19492]        30d42  1036500.247140129   5.892 us |     /* linux:schedule */
   1.003  s [ 19492]       400cb0  1036501.250391833   1.003  s |   } /* sleep */
   3.467 us [ 19492]       400c80  1036501.250395888   4.055 us |   std::operator<<();
            [ 19492]       400d20  1036501.250399777   3.889 us |   std::basic_ostream::operator<<() {
  10.227 us [ 19492]       400d40  1036501.250400067   0.290 us |     std::endl();
  10.742 us [ 19492]       400d20  1036501.250410519  10.452 us |   } /* std::basic_ostream::operator<< */
            [ 19492]               1036501.250575550 165.031 us |   /* linux:task-exit */

uftrace stopped tracing with remaining functions
================================================
task: 19492
[0] b_test

I think the parameter '-r' did not work.

test version:

[root@localhost call_trace]# /usr/local/uftrace/bin/uftrace --version
uftrace v0.12 ( x86_64 dwarf python luajit tui perf sched dynamic )

[namhyung]

The message Usage: --time-range cannot be used with --time-filter shows that the --time-range was not enabled because there is --time-filter option too. Do you happen to have default.opts file in the data directory?

[tbar-hz]

Oh, I see. In record mode, I use "-t 1us" to filter some very short time functions or system events.
I have a big multi-threads program, in long-running mode, business time delay phenomenon happened occasionally.
Almost as many as tens of GB logs will be record if use uftrace, and set "-t 1us" filter condition meanwhile, when the time delay problem happened.
So, I need to search the time point of problem in the large uftrace.data fastly, but the parameter '-r' did not work.
Could you consider support '-r' to search time range in replay mode, when the record mode used '-t' condition?

[namhyung]

Oh, right. I forgot the commit f699ea4 ("uftrace: Store time-filter info to uftrace.data/default.opts") could create the default options for the time filter under the table. The following change should fix the issue.

diff --git a/uftrace.c b/uftrace.c
index 668e9e303d..2b88e49913 100644
--- a/uftrace.c
+++ b/uftrace.c
@@ -616,9 +616,11 @@ static int parse_option(struct opts *opts, int key, char *arg)
                break;
 
        case 't':
-               /* do not override time-filter if it's already set */
-               if (parsing_default_opts && opts->threshold)
-                       break;
+               /* do not override time-filter or time-range if it's already set */
+               if (parsing_default_opts) {
+                       if (opts->threshold || opts->range.start || opts->range.stop)
+                               break;
+               }
 
                /* add time-filter to uftrace.data/default.opts */
                strv_append(&default_opts, "-t");

[tbar-hz]

Thanks！It's ok right now.
But there is a new small problem that the lower boundary of time printed many irrelevant information, and out of the time range.
Like this:

[root@localhost uft]# /usr/local/uftrace/bin/uftrace replay -f time,delta,duration,addr,tid
# DURATION     TID      ADDRESS        TIMESTAMP      TIMEDELTA   FUNCTION
            [ 57229]       9a13c1     9987.158788211            | StreamTcpPacketStateEstablished() {
            [ 57229]       9aad41     9987.158790267   2.056 us |   StreamTcpValidateTimestamp() {
            [ 57229]       99ca14     9987.158790609   0.342 us |     StreamTcpSetOSPolicy() {
            [ 57229]       9dbf5c     9987.158791184   0.575 us |       SCHInfoGetIPv4HostOSFlavour() {
            [ 57229]       9f92c0     9987.158791616   0.432 us |         SCRadixFindKeyIPV4BestMatch() {
            [ 57229]       9f8fd5     9987.158792008   0.392 us |           SCRadixFindKey() {
   1.303 us [ 57229]       9f6928     9987.158794128   2.120 us |             SCMemcmp();
   1.477 us [ 57229]       9f8cd4     9987.158798715   4.587 us |             SCRadixFindKeyIPNetblock();
   8.479 us [ 57229]       9f8fd5     9987.158800487   1.772 us |           } /* SCRadixFindKey */
   9.163 us [ 57229]       9f92c0     9987.158800779   0.292 us |         } /* SCRadixFindKeyIPV4BestMatch */
  10.139 us [ 57229]       9dbf5c     9987.158801323   0.544 us |       } /* SCHInfoGetIPv4HostOSFlavour */
  10.910 us [ 57229]       99ca14     9987.158801519   0.196 us |     } /* StreamTcpSetOSPolicy */
  11.669 us [ 57229]       9aad41     9987.158801936   0.417 us |   } /* StreamTcpValidateTimestamp */
            [ 57229]       9a02e3     9987.158806200   4.264 us |   HandleEstablishedPacketToServer() {
            [ 57229]       9b2086     9987.158817026  10.826 us |     StreamTcpReassembleHandleSegment() {
            [ 57229]       9b202e     9987.158817587   0.561 us |       StreamTcpReassembleHandleSegmentUpdateACK() {
            [ 57229]       9b0eb2     9987.158817787   0.200 us |         StreamTcpReassembleAppLayer() {
   1.831 us [ 57229]       9b0923     9987.158818016   0.229 us |           ReassembleUpdateAppLayer();
   2.909 us [ 57229]       9b0eb2     9987.158820696   2.680 us |         } /* StreamTcpReassembleAppLayer */
   3.324 us [ 57229]       9b202e     9987.158820911   0.215 us |       } /* StreamTcpReassembleHandleSegmentUpdateACK */
   4.168 us [ 57229]       9b2086     9987.158821194   0.283 us |     } /* StreamTcpReassembleHandleSegment */
  15.350 us [ 57229]       9a02e3     9987.158821550   0.356 us |   } /* HandleEstablishedPacketToServer */
  33.528 us [ 57229]       9a13c1     9987.158821739   0.189 us | } /* StreamTcpPacketStateEstablished */

And, use command:
/usr/local/uftrace/bin/uftrace replay -f time,delta,duration,addr,tid -r 9987.158790267~9987.158794128

Then, the filter result as follows:

[root@localhost uft]# /usr/local/uftrace/bin/uftrace replay -f time,delta,duration,addr,tid -r 9987.158790267~9987.158794128
# DURATION     TID      ADDRESS        TIMESTAMP      TIMEDELTA   FUNCTION
            [ 57229]       9aad41     9987.158790267            | StreamTcpValidateTimestamp() {
            [ 57229]       99ca14     9987.158790609   0.342 us |   StreamTcpSetOSPolicy() {
            [ 57229]       9dbf5c     9987.158791184   0.575 us |     SCHInfoGetIPv4HostOSFlavour() {
            [ 57229]       9f92c0     9987.158791616   0.432 us |       SCRadixFindKeyIPV4BestMatch() {
            [ 57229]       9f8fd5     9987.158792008   0.392 us |         SCRadixFindKey() {
            [ 57229]       9f6928     9987.158794128   2.120 us |           SCMemcmp() {
  16.377 us [ 57229]        30d42     9987.174818845  16.024 ms |             /* linux:schedule */
  11.607 us [ 57229]        30d42     9987.181760648   6.941 ms |             /* linux:schedule */
  49.985 us [ 57229]        30d42     9987.185832658   4.072 ms |             /* linux:schedule */
  11.836 us [ 57229]        30d42     9987.189796713   3.964 ms |             /* linux:schedule */
   5.507 us [ 57229]        30d42     9987.189811305  14.592 us |             /* linux:schedule */
  15.228 us [ 57229]        30d42     9987.195630844   5.819 ms |             /* linux:schedule */
  17.591 us [ 57229]        30d42     9987.206133295  10.502 ms |             /* linux:schedule */
  22.059 us [ 57229]        30d42     9987.207866892   1.733 ms |             /* linux:schedule */
  12.631 us [ 57229]        30d42     9987.208853087 986.195 us |             /* linux:schedule */
  11.755 us [ 57229]        30d42     9987.217603577   8.750 ms |             /* linux:schedule */
  18.230 us [ 57229]        30d42     9987.223432588   5.829 ms |             /* linux:schedule */
  10.190 us [ 57229]        30d42     9987.225063079   1.630 ms |             /* linux:schedule */
   9.823 us [ 57229]        30d42     9987.229591220   4.528 ms |             /* linux:schedule */
  12.875 us [ 57229]        30d42     9987.246771925  17.180 ms |             /* linux:schedule */
  19.136 us [ 57229]        30d42     9987.256614175   9.842 ms |             /* linux:schedule */
  15.524 us [ 57229]        30d42     9987.275588766  18.974 ms |             /* linux:schedule */
  16.716 us [ 57229]        30d42     9987.318691177  43.102 ms |             /* linux:schedule */
   7.023 us [ 57229]        30d42     9987.320452350   1.761 ms |             /* linux:schedule */
  12.404 us [ 57229]        30d42     9987.488520061 168.067 ms |             /* linux:schedule */
  11.548 us [ 57229]        30d42     9987.529517842  40.997 ms |             /* linux:schedule */
  10.703 us [ 57229]        30d42     9987.545760558  16.242 ms |             /* linux:schedule */
   8.324 us [ 57229]        30d42     9987.547572582   1.812 ms |             /* linux:schedule */
  11.107 us [ 57229]        30d42     9987.558359503  10.786 ms |             /* linux:schedule */
  12.459 us [ 57229]        30d42     9987.672269290 113.909 ms |             /* linux:schedule */
  14.326 us [ 57229]        30d47     9987.706013196  33.743 ms |             /* linux:schedule (pre-empted) */
  13.614 us [ 57229]        30d42     9987.708891734   2.878 ms |             /* linux:schedule */

if the extra information can be filtered, the meaning of '-r' parameter will be better.

[namhyung]

Thanks for the test. I'll take a look.

[namhyung]

Sorry for the delay. I think we should add this.

diff --git a/utils/perf.c b/utils/perf.c
index 8912e39499..b1a0197fcd 100644
--- a/utils/perf.c
+++ b/utils/perf.c
@@ -413,6 +413,9 @@ static int read_perf_event(struct uftrace_data *handle, struct uftrace_perf_read
        if (unlikely(task == NULL || task->fp == NULL))
                goto again;
 
+       if (!check_time_range(&handle->time_range, perf->time))
+               goto again;
+
        perf->type = h.type;
        perf->valid = true;
        return 0;

[namhyung]

Please check out review/time-range branch.

[tbar-hz]

Please check out review/time-range branch.

It's ok right now, thank you!