sandbox trace errors in CI loop
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 => ----------------------------- Captured stdout call ----------------------------- => Call list dumped to 02000000, size 0xde3b30 => +/tmp/sandbox/tools/proftool -t /tmp/test_trace/trace -o /tmp/test_trace/trace.dat -m /tmp/sandbox/System.map dump-ftrace 9842 functions found in map file, start addr 3e000 call count: 1213676 +trace-cmd dump /tmp/test_trace/trace.dat Tracing meta data in file /tmp/test_trace/trace.dat: [Initial format] 6 [Version] 0 [Little endian] 4 [Bytes in a long] 4096 [Page size, bytes] [Header page, 205 bytes] [Header event, 205 bytes] [Ftrace format, 3 events] [Events format, 0 systems] [Kallsyms, 370293 bytes] [Trace printk, 0 bytes] [Saved command lines, 9 bytes] 1 [CPUs with tracing data] [6 options] [Flyrecord tracing data] [Tracing clock] [local] global counter uptime perf mono mono_raw boot x86-tsc +sh -c trace-cmd report /tmp/test_trace/trace.dat |grep -E '(initf_|initr_)' failed to init data Exit code: 1 =========================== short test summary info ============================ FAILED test/py/tests/test_trace.py::test_trace - ValueError: Exit code: 1 ====================== 1 failed, 1151 deselected in 3.32s ======================
On Thu, Sep 07, 2023 at 05:30:03PM +0200, Michal Simek wrote:
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 =>
I don't get it either since I see this on master with trace options enabled per CI: $ ./u-boot -T arch/sandbox/dts/test.dtb trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 ... rest of boot proceeds ...
So the test should be failing already if that was the problem.
On 9/7/23 20:14, Tom Rini wrote:
On Thu, Sep 07, 2023 at 05:30:03PM +0200, Michal Simek wrote:
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 =>
I don't get it either since I see this on master with trace options enabled per CI: $ ./u-boot -T arch/sandbox/dts/test.dtb trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 ... rest of boot proceeds ...
So the test should be failing already if that was the problem.
I don't thin it is the problematic part.
When I look at https://source.denx.de/u-boot/u-boot/-/blob/master/tools/docker/Dockerfile?r...
clone is done from git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \
https://github.com/rostedt/trace-cmd/blob/master/README#L5
we should be using git://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git instead.
I installed the latest version on my PC and run it via pytest and this is what I am getting. You see that trace-cmd report is returning "failed to init data".
Are we wired to any specific trace-cmd version?
Thanks, Michal
$ ./test/py/test.py -p no:random-order --bd sandbox --build -s -k test_trace +make O=/home/monstr/data/disk/u-boot/build-sandbox -s sandbox_defconfig +make O=/home/monstr/data/disk/u-boot/build-sandbox -s -j12 ==================================================================== test session starts ===================================================================== platform linux -- Python 3.10.12, pytest-6.2.5, py-1.10.0, pluggy-0.13.0 rootdir: /home/monstr/data/disk/u-boot/test/py, configfile: pytest.ini plugins: forked-1.4.0, xdist-2.5.0 collected 1152 items / 1151 deselected / 1 selected
test/py/tests/test_trace.py /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19
U-Boot 2023.10-rc4-00005-gb8dbddc83ab4 (Sep 08 2023 - 12:20:25 +0200)
Reset Status: WARM Reset Status: COLD Model: sandbox DRAM: 256 MiB trace: copying 009a442c bytes of early data from 100000 to 0e000000 658075 traced function calls trace: enabled Core: 275 devices, 97 uclasses, devicetree: board WDT: Not starting wdt-gpio-toggle wdt_gpio wdt-gpio-level: Request for wdt gpio failed: -16 WDT: Not starting wdt@0 MMC: Can't map file 'mmc1.img': Invalid argument mmc1: Unable to map file 'mmc1.img' Can't map file 'mmc1.img': Invalid argument mmc1: Unable to map file 'mmc1.img' mmc1 - probe failed: -1 mmc2: 2 (SD)Can't map file 'mmc1.img': Invalid argument mmc1: Unable to map file 'mmc1.img' , mmc0: 0 (SD) Loading Environment from nowhere... OK In: serial,cros-ec-keyb,usbkbd Out: serial,vidconsole Err: serial,vidconsole Model: sandbox Net: eth0: eth@10002000, eth5: eth@10003000, eth3: sbe5, eth6: eth@10004000, eth8: phy-test-eth, eth4: dsa-test-eth, eth2: lan0, eth7: lan1 Hit any key to stop autoboot: 0 => => trace pause => => trace stats 276,625 function sites 1,568,061 function calls 0 untracked function calls 1,213,676 traced function calls (898312 dropped due to overflow) 36 maximum observed call depth 15 call depth limit 1,024,122 calls not traced due to depth 1,213,676 max function calls
trace buffer e000000 call records e21c4e8 => => bootstage report Timer summary in microseconds (10 records): Mark Elapsed Stage 0 0 reset 0 0 board_init_f 40,753 40,753 board_init_r 91,689 50,936 eth_common_init 91,699 10 eth_initialize 93,786 2,087 main_loop 94,644 858 cli_loop
Accumulated time: 10,148 dm_r 11,269 of_live 25,652 dm_f => => trace calls 2000000 1000000 Call list dumped to 02000000, size 0xde3b30 => Call list dumped to 02000000, size 0xde3b30 => host save hostfs - 2000000 /tmp/test_trace/trace ${profoffset} 14564144 bytes written in 3 ms (4.5 GiB/s) => +/home/monstr/data/disk/u-boot/build-sandbox/tools/proftool -t /tmp/test_trace/trace -o /tmp/test_trace/trace.dat -m /home/monstr/data/disk/u-boot/build-sandbox/System.map dump-ftrace 9842 functions found in map file, start addr 3e000 call count: 1213676 +trace-cmd dump /tmp/test_trace/trace.dat
Tracing meta data in file /tmp/test_trace/trace.dat: [Initial format] 6 [Version] 0 [Little endian] 4 [Bytes in a long] 4096 [Page size, bytes] [Header page, 205 bytes] [Header event, 205 bytes] [Ftrace format, 3 events] [Events format, 0 systems] [Kallsyms, 370293 bytes] [Trace printk, 0 bytes] [Saved command lines, 9 bytes] 1 [CPUs with tracing data] [6 options] [Flyrecord tracing data] [Tracing clock] [local] global counter uptime perf mono mono_raw boot x86-tsc
+sh -c trace-cmd report /tmp/test_trace/trace.dat |grep -E '(initf_|initr_)' failed to init data Exit code: 1 F
========================================================================== FAILURES ========================================================================== _________________________________________________________________________ test_trace _________________________________________________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ================================================================== short test summary info =================================================================== FAILED test/py/tests/test_trace.py::test_trace - ValueError: Exit code: 1 ============================================================= 1 failed, 1151 deselected in 2.13s =============================================================
On Fri, Sep 08, 2023 at 12:24:10PM +0200, Michal Simek wrote:
On 9/7/23 20:14, Tom Rini wrote:
On Thu, Sep 07, 2023 at 05:30:03PM +0200, Michal Simek wrote:
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 =>
I don't get it either since I see this on master with trace options enabled per CI: $ ./u-boot -T arch/sandbox/dts/test.dtb trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 ... rest of boot proceeds ...
So the test should be failing already if that was the problem.
I don't thin it is the problematic part.
When I look at https://source.denx.de/u-boot/u-boot/-/blob/master/tools/docker/Dockerfile?r...
clone is done from git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \
https://github.com/rostedt/trace-cmd/blob/master/README#L5
we should be using git://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git instead.
I installed the latest version on my PC and run it via pytest and this is what I am getting. You see that trace-cmd report is returning "failed to init data".
Are we wired to any specific trace-cmd version?
Wait, no, what's going on exactly? The github repository is a mirror of the kernel.org one. So yes, we should correct to point to the main one, but the top of tree in both cases is commit 354dccca52e805ce1b22e2b62cbae8c265886c27.
On 9/8/23 15:34, Tom Rini wrote:
On Fri, Sep 08, 2023 at 12:24:10PM +0200, Michal Simek wrote:
On 9/7/23 20:14, Tom Rini wrote:
On Thu, Sep 07, 2023 at 05:30:03PM +0200, Michal Simek wrote:
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 =>
I don't get it either since I see this on master with trace options enabled per CI: $ ./u-boot -T arch/sandbox/dts/test.dtb trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 ... rest of boot proceeds ...
So the test should be failing already if that was the problem.
I don't thin it is the problematic part.
When I look at https://source.denx.de/u-boot/u-boot/-/blob/master/tools/docker/Dockerfile?r...
clone is done from git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \
https://github.com/rostedt/trace-cmd/blob/master/README#L5
we should be using git://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git instead.
I installed the latest version on my PC and run it via pytest and this is what I am getting. You see that trace-cmd report is returning "failed to init data".
Are we wired to any specific trace-cmd version?
Wait, no, what's going on exactly? The github repository is a mirror of the kernel.org one. So yes, we should correct to point to the main one, but the top of tree in both cases is commit 354dccca52e805ce1b22e2b62cbae8c265886c27.
I dig into it more. What it is happening is that when sandbox u-boot is bigger trace.dat file is placing information to different offset then it is recorded somewhere in header.
Wrong placement
0005b000 20 70 65 72 66 20 6d 6f 6e 6f 20 6d 6f 6e 6f 5f | perf mono mono_| 0005b010 72 61 77 20 62 6f 6f 74 20 78 38 36 2d 74 73 63 |raw boot x86-tsc| 0005b020 0a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| 0005b030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| * 0005c000 89 df f6 1d 00 00 00 00 dc 0f 00 00 00 00 00 00 |................| 0005c010 06 00 00 00 01 00 00 00 01 00 00 00 af e5 0a 00 |................| 0005c020 00 00 00 00 ef dc 09 00 00 00 00 00 06 00 00 00 |................| 0005c030 01 00 00 00 01 00 00 00 af e5 0a 00 00 00 00 00 |................|
Correct placement for trace-cmd
0005aee0 75 70 74 69 6d 65 20 70 65 72 66 20 6d 6f 6e 6f |uptime perf mono| 0005aef0 20 6d 6f 6e 6f 5f 72 61 77 20 62 6f 6f 74 20 78 | mono_raw boot x| 0005af00 38 36 2d 74 73 63 0a 00 00 00 00 00 00 00 00 00 |86-tsc..........| 0005af10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| * 0005b000 36 f8 92 3f 00 00 00 00 e0 0f 00 00 00 00 00 00 |6..?............|
And trace-cmd want to decode data available at 0x5b000 offset in both cases.
It means I expect proftool is not correctly generating offset where data is present. I don't understand how it works but I clearly see based on trace-cmd that it points to incorrect location.
Thanks, Michal
Hi Tom,
pá 8. 9. 2023 v 15:42 odesílatel Michal Simek monstr@monstr.eu napsal:
On 9/8/23 15:34, Tom Rini wrote:
On Fri, Sep 08, 2023 at 12:24:10PM +0200, Michal Simek wrote:
On 9/7/23 20:14, Tom Rini wrote:
On Thu, Sep 07, 2023 at 05:30:03PM +0200, Michal Simek wrote:
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 =>
I don't get it either since I see this on master with trace options enabled per CI: $ ./u-boot -T arch/sandbox/dts/test.dtb trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 ... rest of boot proceeds ...
So the test should be failing already if that was the problem.
I don't thin it is the problematic part.
When I look at https://source.denx.de/u-boot/u-boot/-/blob/master/tools/docker/Dockerfile?r...
clone is done from git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \
https://github.com/rostedt/trace-cmd/blob/master/README#L5
we should be using git://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git instead.
I installed the latest version on my PC and run it via pytest and this is what I am getting. You see that trace-cmd report is returning "failed to init data".
Are we wired to any specific trace-cmd version?
Wait, no, what's going on exactly? The github repository is a mirror of the kernel.org one. So yes, we should correct to point to the main one, but the top of tree in both cases is commit 354dccca52e805ce1b22e2b62cbae8c265886c27.
I dig into it more. What it is happening is that when sandbox u-boot is bigger trace.dat file is placing information to different offset then it is recorded somewhere in header.
Wrong placement
0005b000 20 70 65 72 66 20 6d 6f 6e 6f 20 6d 6f 6e 6f 5f | perf mono mono_| 0005b010 72 61 77 20 62 6f 6f 74 20 78 38 36 2d 74 73 63 |raw boot x86-tsc| 0005b020 0a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| 0005b030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
0005c000 89 df f6 1d 00 00 00 00 dc 0f 00 00 00 00 00 00 |................| 0005c010 06 00 00 00 01 00 00 00 01 00 00 00 af e5 0a 00 |................| 0005c020 00 00 00 00 ef dc 09 00 00 00 00 00 06 00 00 00 |................| 0005c030 01 00 00 00 01 00 00 00 af e5 0a 00 00 00 00 00 |................|
Correct placement for trace-cmd
0005aee0 75 70 74 69 6d 65 20 70 65 72 66 20 6d 6f 6e 6f |uptime perf mono| 0005aef0 20 6d 6f 6e 6f 5f 72 61 77 20 62 6f 6f 74 20 78 | mono_raw boot x| 0005af00 38 36 2d 74 73 63 0a 00 00 00 00 00 00 00 00 00 |86-tsc..........| 0005af10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
0005b000 36 f8 92 3f 00 00 00 00 e0 0f 00 00 00 00 00 00 |6..?............|
And trace-cmd want to decode data available at 0x5b000 offset in both cases.
It means I expect proftool is not correctly generating offset where data is present. I don't understand how it works but I clearly see based on trace-cmd that it points to incorrect location.
diff --git a/tools/proftool.c b/tools/proftool.c index 101bcb63334e..815e01efb5d1 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -1500,7 +1500,7 @@ static int write_flyrecord(struct twriter *tw, enum out_format_t out_format, tw->ptr += fprintf(fout, "flyrecord%c", 0);
/* trace data */ - start = ALIGN(tw->ptr + 16, TRACE_PAGE_SIZE); + start = ALIGN(tw->ptr + 16, 0x4000); tw->ptr += tputq(fout, start);
/* use a placeholder for the size */
This is the problematic code. In flyrecord section in header there is the calculation where data start. And there is tw->ptr +16 used (not sure why +16) but actual flyrecord is much bigger than 16.
In my case start of flyrecord is 0x5afc1 + flyrecordX + 16 (mentioned above) is 0x5afdb. Then there is page alignment which gives 0x5b000 which is recorded but actual size is till 0x5b021.
The actual size of the header is 0x60 not flyrecordX + 16 (based on location where tw->ptr is taken). Simon: Do you agree with this logic?
It was introduced by commit be16fc81b2ed ("trace: Update proftool to use new binary format").
Thanks, Michal
Hi Michal,
On Fri, 8 Sept 2023 at 09:00, Michal Simek monstr@monstr.eu wrote:
Hi Tom,
pá 8. 9. 2023 v 15:42 odesílatel Michal Simek monstr@monstr.eu napsal:
On 9/8/23 15:34, Tom Rini wrote:
On Fri, Sep 08, 2023 at 12:24:10PM +0200, Michal Simek wrote:
On 9/7/23 20:14, Tom Rini wrote:
On Thu, Sep 07, 2023 at 05:30:03PM +0200, Michal Simek wrote:
Hi Simon and Tom,
I am preparing pull request and I see that CI loop is reporting issue with sandbox trace and I have no idea what's going wrong here.
This is the first problematic commit but have no clue what it has to do with trace.
https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/commit/8c5f80d1...
If you have an access you can take a look at my queue to see that only this job is failing. https://source.denx.de/u-boot/custodians/u-boot-microblaze/-/pipelines
Thanks, Michal
collected 1152 items / 1151 deselected / 1 selected test/py/tests/test_trace.py F [100%] =================================== FAILURES =================================== __________________________________ test_trace __________________________________ test/py/tests/test_trace.py:292: in test_trace check_function(cons, fname, proftool, map_fname, trace_dat) test/py/tests/test_trace.py:117: in check_function out = util.run_and_log(cons, ['sh', '-c', cmd]) test/py/u_boot_utils.py:181: in run_and_log output = runner.run(cmd, ignore_errors=ignore_errors, stdin=stdin, env=env) test/py/multiplexed_log.py:183: in run raise exception E ValueError: Exit code: 1 ---------------------------- Captured stdout setup ----------------------------- /u-boot trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 =>
I don't get it either since I see this on master with trace options enabled per CI: $ ./u-boot -T arch/sandbox/dts/test.dtb trace: early enable at 00100000 sandbox_serial serial: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19 ... rest of boot proceeds ...
So the test should be failing already if that was the problem.
I don't thin it is the problematic part.
When I look at https://source.denx.de/u-boot/u-boot/-/blob/master/tools/docker/Dockerfile?r...
clone is done from git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \
https://github.com/rostedt/trace-cmd/blob/master/README#L5
we should be using git://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git instead.
I installed the latest version on my PC and run it via pytest and this is what I am getting. You see that trace-cmd report is returning "failed to init data".
Are we wired to any specific trace-cmd version?
Wait, no, what's going on exactly? The github repository is a mirror of the kernel.org one. So yes, we should correct to point to the main one, but the top of tree in both cases is commit 354dccca52e805ce1b22e2b62cbae8c265886c27.
I dig into it more. What it is happening is that when sandbox u-boot is bigger trace.dat file is placing information to different offset then it is recorded somewhere in header.
Wrong placement
0005b000 20 70 65 72 66 20 6d 6f 6e 6f 20 6d 6f 6e 6f 5f | perf mono mono_| 0005b010 72 61 77 20 62 6f 6f 74 20 78 38 36 2d 74 73 63 |raw boot x86-tsc| 0005b020 0a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| 0005b030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
0005c000 89 df f6 1d 00 00 00 00 dc 0f 00 00 00 00 00 00 |................| 0005c010 06 00 00 00 01 00 00 00 01 00 00 00 af e5 0a 00 |................| 0005c020 00 00 00 00 ef dc 09 00 00 00 00 00 06 00 00 00 |................| 0005c030 01 00 00 00 01 00 00 00 af e5 0a 00 00 00 00 00 |................|
Correct placement for trace-cmd
0005aee0 75 70 74 69 6d 65 20 70 65 72 66 20 6d 6f 6e 6f |uptime perf mono| 0005aef0 20 6d 6f 6e 6f 5f 72 61 77 20 62 6f 6f 74 20 78 | mono_raw boot x| 0005af00 38 36 2d 74 73 63 0a 00 00 00 00 00 00 00 00 00 |86-tsc..........| 0005af10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
0005b000 36 f8 92 3f 00 00 00 00 e0 0f 00 00 00 00 00 00 |6..?............|
And trace-cmd want to decode data available at 0x5b000 offset in both cases.
It means I expect proftool is not correctly generating offset where data is present. I don't understand how it works but I clearly see based on trace-cmd that it points to incorrect location.
diff --git a/tools/proftool.c b/tools/proftool.c index 101bcb63334e..815e01efb5d1 100644 --- a/tools/proftool.c +++ b/tools/proftool.c @@ -1500,7 +1500,7 @@ static int write_flyrecord(struct twriter *tw, enum out_format_t out_format, tw->ptr += fprintf(fout, "flyrecord%c", 0);
/* trace data */
start = ALIGN(tw->ptr + 16, TRACE_PAGE_SIZE);
start = ALIGN(tw->ptr + 16, 0x4000); tw->ptr += tputq(fout, start); /* use a placeholder for the size */This is the problematic code. In flyrecord section in header there is the calculation where data start. And there is tw->ptr +16 used (not sure why +16) but actual flyrecord is much bigger than 16.
In my case start of flyrecord is 0x5afc1 + flyrecordX + 16 (mentioned above) is 0x5afdb. Then there is page alignment which gives 0x5b000 which is recorded but actual size is till 0x5b021.
The actual size of the header is 0x60 not flyrecordX + 16 (based on location where tw->ptr is taken). Simon: Do you agree with this logic?
It was introduced by commit be16fc81b2ed ("trace: Update proftool to use new binary format").
If you can fix it then yes that is fine and please send a patch. The test is there to catch things going wrong. The intent of proftool is to mimic the flyrecord format used by Linux. Your analysis seems right to me.
Regards, Simon
participants (3)
-
Michal Simek -
Simon Glass -
Tom Rini