sandbox trace errors in CI loop
Michal Simek
monstr at monstr.eu
Fri Sep 8 12:24:10 CEST 2023
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/8c5f80d11b29536979ac41a6087fb8938f45bbf2
>>
>> 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?ref_type=heads#L225
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 at 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 at 10002000, eth5: eth at 10003000, eth3: sbe5, eth6: eth at 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 =============================================================
--
Michal Simek, Ing. (M.Eng), OpenPGP -> KeyID: FE3D1F91
w: www.monstr.eu p: +42-0-721842854
Maintainer of Linux kernel - Xilinx Microblaze
Maintainer of Linux kernel - Xilinx Zynq ARM and ZynqMP/Versal ARM64 SoCs
U-Boot custodian - Xilinx Microblaze/Zynq/ZynqMP/Versal/Versal NET SoCs
TF-A maintainer - Xilinx ZynqMP/Versal/Versal NET SoCs
More information about the U-Boot
mailing list