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 =============================================================