0

I'm working on an arm board running an old kernel(3.14.29)

I trying to to get the dmesg output and pass it to the bootgraph.pl to generate an SVG of kernel boot sequence. However after passing the dmesg output to bootgraph.pl I get:

Illegal division by zero at bootgraph.pl line 179

After some digging, I found out that the timestamp of the busybox dmesg output is not standard.

So for example in the standard dmesg provided by util-linux the output is this:

[    0.037644] calling  trace_init_flags_sys_exit+0x0/0x14 @ 1
[    0.037650] initcall trace_init_flags_sys_exit+0x0/0x14 returned 0 after 0 usecs
[    0.037656] calling  trace_init_flags_sys_enter+0x0/0x14 @ 1
[    0.037661] initcall trace_init_flags_sys_enter+0x0/0x14 returned 0 after 0 usecs
[    0.037666] calling  init_hw_perf_events+0x0/0x150 @ 1
[    0.037670] hw perfevents: enabled with arm/armv8-pmuv3 PMU driver, 7 counters available
[    0.037697] initcall init_hw_perf_events+0x0/0x150 returned 0 after 0 usecs
[    0.037701] calling  cpu_suspend_init+0x0/0xa4 @ 1
[    0.037707] initcall cpu_suspend_init+0x0/0xa4 returned 0 after 0 usecs
[    0.037713] calling  spawn_ksoftirqd+0x0/0x64 @ 1
[    0.057161] initcall spawn_ksoftirqd+0x0/0x64 returned 0 after 19531 usecs

while the output of the busybox dmesg looks like the following:

[    0.037644@0] calling  trace_init_flags_sys_exit+0x0/0x14 @ 1
[    0.037650@0] initcall trace_init_flags_sys_exit+0x0/0x14 returned 0 after 0 usecs
[    0.037656@0] calling  trace_init_flags_sys_enter+0x0/0x14 @ 1
[    0.037661@0] initcall trace_init_flags_sys_enter+0x0/0x14 returned 0 after 0 usecs
[    0.037666@0] calling  init_hw_perf_events+0x0/0x150 @ 1
[    0.037670@0] hw perfevents: enabled with arm/armv8-pmuv3 PMU driver, 7 counters available
[    0.037697@0] initcall init_hw_perf_events+0x0/0x150 returned 0 after 0 usecs
[    0.037701@0] calling  cpu_suspend_init+0x0/0xa4 @ 1
[    0.037707@0] initcall cpu_suspend_init+0x0/0xa4 returned 0 after 0 usecs
[    0.037713@0] calling  spawn_ksoftirqd+0x0/0x64 @ 1
[    0.057161@0] initcall spawn_ksoftirqd+0x0/0x64 returned 0 after 19531 usecs

The problem in the second output is the @ sign and the number after it [ 0.037661@0] , after removing all the occurrences of this substring bootgraph.pl was able to parse the log and generate the SVG.

So my question is what does this string (@0) refer to and can I remove it from busybox dmesg output?

EDIT: note that looking at the serial console as the board boots, I see the same messages as the busybox dmesg (the second format with the @digit), So I think the problem related to the old kernel having a different format, So was there any changes regarding this in the kernel after version 3.14.29? or is this added to the kernel by the board vender?

  • I don't see off-hand where busybox's dmesg is adding a @0; do you get the same output with dmesg -r (for raw mode)? I suspect all that may do is print leading <(digits)> – Jeff Schaller Jun 23 '18 at 1:33
  • Well, running busybox dmesg produces the same format with the added log level <6>[ 6.912810@3] Bluetooth: BNEP filters: protocol multicast I don't think the problem is in the busybox dmesg instead it's in the kernel (3.14.29) because even when the kernel boot's I can see in the serial console the same format, for some reason the busybox dmesg print the messages as they are and the util-linux dmesg strips the @digit` part – MOHAMMAD RASIM Jun 23 '18 at 5:39
  • indeed, the parse_syslog_timestamp function uses strtol (which stops at the @), and then returns a pointer that's skipped over the timestamp (after saving it). – Jeff Schaller Jun 24 '18 at 0:09
  • @JeffSchaller Great, So what does @digit signify? – MOHAMMAD RASIM Jun 24 '18 at 6:08

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.