From: Philippe Proulx via lttng-dev <lttng-dev@lists.lttng.org> To: "Kim, Seongab" <Seongab.Kim@harman.com> Cc: "lttng-dev@lists.lttng.org" <lttng-dev@lists.lttng.org> Subject: Re: difference of timestamp between babeltrace and python binding Date: Wed, 22 Jul 2020 10:56:57 -0400 [thread overview] Message-ID: <CAB4xu_3=6yYndO-C49FQ=hXF4eC+f6WGgMQCJ9-GhbA4zQ8mCQ@mail.gmail.com> (raw) In-Reply-To: <15ed8d31ec16483db50928860aa4a4e5@HIMDWSMB06.ad.harman.com> On Wed, Jul 22, 2020 at 9:17 AM Kim, Seongab via lttng-dev <lttng-dev@lists.lttng.org> wrote: > > Hi, Hello. See my comments below. > > I found that the timestamps from babeltrace and python binding are different in nanoseconds level. > > skim@d54030999178:~/ssd_work/traces$ python3 test.py ./trace/ | head -n 10 > 2019-12-12 13:45:40.098212096 (+0.000000 s): syscall_exit_ppoll > 2019-12-12 13:45:40.098213608 (+0.000001 s): rcu_utilization > 2019-12-12 13:45:40.098214632 (+0.000001 s): syscall_entry_ioctl > 2019-12-12 13:45:40.098214888 (+0.000000 s): kmem_kfree > 2019-12-12 13:45:40.098214144 (+0.000000 s): rcu_utilization > 2019-12-12 13:45:40.098215168 (+0.000001 s): sched_stat_runtime > 2019-12-12 13:45:40.098220776 (+0.000004 s): sched_switch > 2019-12-12 13:45:40.098221312 (+0.000002 s): timer_hrtimer_cancel > 2019-12-12 13:45:40.098221312 (+0.000000 s): kmem_kmalloc > 2019-12-12 13:45:40.098223360 (+0.000002 s): kmem_kfree > Traceback (most recent call last): > File "test.py", line 33, in <module> > print(fmt.format(dt, ns_from_origin % 1e3, diff_s, msg.event.name)) > BrokenPipeError: [Errno 32] Broken pipe > skim@d54030999178:~/ssd_work/traces$ babeltrace2 ./trace/ | head -n 10 > [13:45:40.098211969] (+?.?????????) test-sys syscall_exit_ppoll: { cpu_id = 3 }, { ret = 0, nfds = 1, fds_length = 0, overflow = 0, fds =[ ] } > [13:45:40.098212481] (+0.000000512) test-sys rcu_utilization: { cpu_id = 5 }, { s = "Start context switch" } > [13:45:40.098213729] (+0.000001248) test-sys syscall_entry_ioctl: { cpu_id = 2 }, { fd = 24, cmd = 1075331408, arg = 547894601712 } > [13:45:40.098213953] (+0.000000224) test-sys kmem_kfree: { cpu_id = 3 }, { call_site = 0xFFFFFF800153B274, ptr = 0x0 } > [13:45:40.098214017] (+0.000000064) test-sys rcu_utilization: { cpu_id = 5 }, { s = "End context switch" } > [13:45:40.098215201] (+0.000001184) test-sys sched_stat_runtime: { cpu_id = 5 }, { comm = "Positioning", tid = 1056, runtime = 38048, vruntime = 2125241692 } > [13:45:40.098219681] (+0.000004480) test-sys sched_switch: { cpu_id = 5 }, { prev_comm = "Positioning", prev_tid = 1056, prev_prio = 15, prev_state = 1, next_comm = "Sensor", next_tid = 1061, next_prio = 15 } > [13:45:40.098221313] (+0.000001632) test-sys timer_hrtimer_cancel: { cpu_id = 5 }, { hrtimer = 0xFFFFFFC257807CD8 } > [13:45:40.098221409] (+0.000000096) test-sys kmem_kmalloc: { cpu_id = 0 }, { call_site = 0xFFFFFF80014A27EC, ptr = 0xFFFFFFC04EDFA400, bytes_req = 739, bytes_alloc = 1024, gfp_flags = 37748928 } > [13:45:40.098223361] (+0.000001952) test-sys kmem_kfree: { cpu_id = 5 }, { call_site = 0xFFFFFF8008164C58, ptr = 0x0 } > > The difference is not consistent and Trace Compass shows the same timestamp with the babeltrace output, so I think something is wrong in my python code. > I just modified the example script from https://babeltrace.org/docs/v2.0/python/bt2/examples.html#get-an-event-s-time to show nanoseconds as below. > > diff: > > 32,33c32,33 > < fmt = '{} (+{:.6f} s): {}' > < print(fmt.format(dt, diff_s, msg.event.name)) > --- > > fmt = '{}{:03.0f} (+{:.6f} s): {}' > > print(fmt.format(dt, ns_from_origin % 1e3, diff_s, msg.event.name)) > > Full code: > > import bt2 > import sys > import datetime > > # Create a trace collection message iterator from the first command-line > # argument. > msg_it = bt2.TraceCollectionMessageIterator(sys.argv[1]) > > # Last event's time (ns from origin). > last_event_ns_from_origin = None > > # Iterate the trace messages. > for msg in msg_it: > # `bt2._EventMessageConst` is the Python type of an event message. > if type(msg) is bt2._EventMessageConst: > # Get event message's default clock snapshot's ns from origin > # value. > ns_from_origin = msg.default_clock_snapshot.ns_from_origin > > # Compute the time difference since the last event message. > diff_s = 0 > > if last_event_ns_from_origin is not None: > diff_s = (ns_from_origin - last_event_ns_from_origin) / 1e9 > > # Create a `datetime.datetime` object from `ns_from_origin` for > # presentation. Note that such an object is less accurate than > # `ns_from_origin` as it holds microseconds, not nanoseconds. > dt = datetime.datetime.fromtimestamp(ns_from_origin / 1e9) This rounds the µs part. With 1509556783964792907, the µs part becomes 964793. That's one issue. > > # Print line. > fmt = '{}{:03.0f} (+{:.6f} s): {}' > print(fmt.format(dt, ns_from_origin % 1e3, diff_s, msg.event.name)) `type(1e3)` is `float`. You get an inaccurate floating point division operation here instead of an integral one. Do: ns_from_origin % 1000 or ns_from_origin % int(1e3) instead. Hope this helps, Phil > > # Update last event's time. > last_event_ns_from_origin = ns_from_origin > > Could someone help what was wrong in the python code? Or is this a bug in ns_from_origin implementation? _______________________________________________ lttng-dev mailing list lttng-dev@lists.lttng.org https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
WARNING: multiple messages have this Message-ID (diff)
From: Philippe Proulx via lttng-dev <lttng-dev@lists.lttng.org> To: "Kim, Seongab" <Seongab.Kim@harman.com> Cc: "lttng-dev@lists.lttng.org" <lttng-dev@lists.lttng.org> Subject: Re: [lttng-dev] difference of timestamp between babeltrace and python binding Date: Wed, 22 Jul 2020 10:56:57 -0400 [thread overview] Message-ID: <CAB4xu_3=6yYndO-C49FQ=hXF4eC+f6WGgMQCJ9-GhbA4zQ8mCQ@mail.gmail.com> (raw) Message-ID: <20200722145657.uyLQLqZDCwbkHPQ_r1hSNqVcnRrpx4xpyAreywfszRU@z> (raw) In-Reply-To: <15ed8d31ec16483db50928860aa4a4e5@HIMDWSMB06.ad.harman.com> On Wed, Jul 22, 2020 at 9:17 AM Kim, Seongab via lttng-dev <lttng-dev@lists.lttng.org> wrote: > > Hi, Hello. See my comments below. > > I found that the timestamps from babeltrace and python binding are different in nanoseconds level. > > skim@d54030999178:~/ssd_work/traces$ python3 test.py ./trace/ | head -n 10 > 2019-12-12 13:45:40.098212096 (+0.000000 s): syscall_exit_ppoll > 2019-12-12 13:45:40.098213608 (+0.000001 s): rcu_utilization > 2019-12-12 13:45:40.098214632 (+0.000001 s): syscall_entry_ioctl > 2019-12-12 13:45:40.098214888 (+0.000000 s): kmem_kfree > 2019-12-12 13:45:40.098214144 (+0.000000 s): rcu_utilization > 2019-12-12 13:45:40.098215168 (+0.000001 s): sched_stat_runtime > 2019-12-12 13:45:40.098220776 (+0.000004 s): sched_switch > 2019-12-12 13:45:40.098221312 (+0.000002 s): timer_hrtimer_cancel > 2019-12-12 13:45:40.098221312 (+0.000000 s): kmem_kmalloc > 2019-12-12 13:45:40.098223360 (+0.000002 s): kmem_kfree > Traceback (most recent call last): > File "test.py", line 33, in <module> > print(fmt.format(dt, ns_from_origin % 1e3, diff_s, msg.event.name)) > BrokenPipeError: [Errno 32] Broken pipe > skim@d54030999178:~/ssd_work/traces$ babeltrace2 ./trace/ | head -n 10 > [13:45:40.098211969] (+?.?????????) test-sys syscall_exit_ppoll: { cpu_id = 3 }, { ret = 0, nfds = 1, fds_length = 0, overflow = 0, fds =[ ] } > [13:45:40.098212481] (+0.000000512) test-sys rcu_utilization: { cpu_id = 5 }, { s = "Start context switch" } > [13:45:40.098213729] (+0.000001248) test-sys syscall_entry_ioctl: { cpu_id = 2 }, { fd = 24, cmd = 1075331408, arg = 547894601712 } > [13:45:40.098213953] (+0.000000224) test-sys kmem_kfree: { cpu_id = 3 }, { call_site = 0xFFFFFF800153B274, ptr = 0x0 } > [13:45:40.098214017] (+0.000000064) test-sys rcu_utilization: { cpu_id = 5 }, { s = "End context switch" } > [13:45:40.098215201] (+0.000001184) test-sys sched_stat_runtime: { cpu_id = 5 }, { comm = "Positioning", tid = 1056, runtime = 38048, vruntime = 2125241692 } > [13:45:40.098219681] (+0.000004480) test-sys sched_switch: { cpu_id = 5 }, { prev_comm = "Positioning", prev_tid = 1056, prev_prio = 15, prev_state = 1, next_comm = "Sensor", next_tid = 1061, next_prio = 15 } > [13:45:40.098221313] (+0.000001632) test-sys timer_hrtimer_cancel: { cpu_id = 5 }, { hrtimer = 0xFFFFFFC257807CD8 } > [13:45:40.098221409] (+0.000000096) test-sys kmem_kmalloc: { cpu_id = 0 }, { call_site = 0xFFFFFF80014A27EC, ptr = 0xFFFFFFC04EDFA400, bytes_req = 739, bytes_alloc = 1024, gfp_flags = 37748928 } > [13:45:40.098223361] (+0.000001952) test-sys kmem_kfree: { cpu_id = 5 }, { call_site = 0xFFFFFF8008164C58, ptr = 0x0 } > > The difference is not consistent and Trace Compass shows the same timestamp with the babeltrace output, so I think something is wrong in my python code. > I just modified the example script from https://babeltrace.org/docs/v2.0/python/bt2/examples.html#get-an-event-s-time to show nanoseconds as below. > > diff: > > 32,33c32,33 > < fmt = '{} (+{:.6f} s): {}' > < print(fmt.format(dt, diff_s, msg.event.name)) > --- > > fmt = '{}{:03.0f} (+{:.6f} s): {}' > > print(fmt.format(dt, ns_from_origin % 1e3, diff_s, msg.event.name)) > > Full code: > > import bt2 > import sys > import datetime > > # Create a trace collection message iterator from the first command-line > # argument. > msg_it = bt2.TraceCollectionMessageIterator(sys.argv[1]) > > # Last event's time (ns from origin). > last_event_ns_from_origin = None > > # Iterate the trace messages. > for msg in msg_it: > # `bt2._EventMessageConst` is the Python type of an event message. > if type(msg) is bt2._EventMessageConst: > # Get event message's default clock snapshot's ns from origin > # value. > ns_from_origin = msg.default_clock_snapshot.ns_from_origin > > # Compute the time difference since the last event message. > diff_s = 0 > > if last_event_ns_from_origin is not None: > diff_s = (ns_from_origin - last_event_ns_from_origin) / 1e9 > > # Create a `datetime.datetime` object from `ns_from_origin` for > # presentation. Note that such an object is less accurate than > # `ns_from_origin` as it holds microseconds, not nanoseconds. > dt = datetime.datetime.fromtimestamp(ns_from_origin / 1e9) This rounds the µs part. With 1509556783964792907, the µs part becomes 964793. That's one issue. > > # Print line. > fmt = '{}{:03.0f} (+{:.6f} s): {}' > print(fmt.format(dt, ns_from_origin % 1e3, diff_s, msg.event.name)) `type(1e3)` is `float`. You get an inaccurate floating point division operation here instead of an integral one. Do: ns_from_origin % 1000 or ns_from_origin % int(1e3) instead. Hope this helps, Phil > > # Update last event's time. > last_event_ns_from_origin = ns_from_origin > > Could someone help what was wrong in the python code? Or is this a bug in ns_from_origin implementation? _______________________________________________ lttng-dev mailing list lttng-dev@lists.lttng.org https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
next prev parent reply other threads:[~2020-07-22 14:57 UTC|newest] Thread overview: 6+ messages / expand[flat|nested] mbox.gz Atom feed top 2020-07-22 6:30 difference of timestamp between babeltrace and python binding Kim, Seongab via lttng-dev 2020-07-22 6:30 ` [lttng-dev] " Kim, Seongab via lttng-dev 2020-07-22 14:56 ` Philippe Proulx via lttng-dev [this message] 2020-07-22 14:56 ` Philippe Proulx via lttng-dev 2020-07-23 5:43 ` [EXTERNAL] " Kim, Seongab via lttng-dev 2020-07-23 5:43 ` [lttng-dev] " Kim, Seongab via lttng-dev
Reply instructions: You may reply publicly to this message via plain-text email using any one of the following methods: * Save the following mbox file, import it into your mail client, and reply-to-all from there: mbox Avoid top-posting and favor interleaved quoting: https://en.wikipedia.org/wiki/Posting_style#Interleaved_style * Reply using the --to, --cc, and --in-reply-to switches of git-send-email(1): git send-email \ --in-reply-to='CAB4xu_3=6yYndO-C49FQ=hXF4eC+f6WGgMQCJ9-GhbA4zQ8mCQ@mail.gmail.com' \ --to=lttng-dev@lists.lttng.org \ --cc=Seongab.Kim@harman.com \ --cc=eeppeliteloop@gmail.com \ /path/to/YOUR_REPLY https://kernel.org/pub/software/scm/git/docs/git-send-email.html * If your mail client supports setting the In-Reply-To header via mailto: links, try the mailto: linkBe sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).