* schedule delay 15ms @ 2025-11-12 6:09 JerryJun 2025-11-12 8:23 ` Jan Kiszka 0 siblings, 1 reply; 11+ messages in thread From: JerryJun @ 2025-11-12 6:09 UTC (permalink / raw) To: xenomai@lists.linux.dev [-- Attachment #1: Type: text/plain, Size: 15883 bytes --] hi： We are encountering some scheduling issues. Within a 15ms time interval (99058.151147 -> 99058.167775), no real-time threads were scheduled, including the swapper idle thread. We have a 1ms-polling-rt-task running on CPU1, but it was also not scheduled during this period. Even the RTDM interrupts from peripherals were not responded to or processed. What could be the reason for this? Architecture： x86_64 linux kernel：5.10.199-dovetail1 cobalt：3.2.4 kernel cmdline: xenomai.supported_cpus=0xf idle=halt nosmap Thread-name CPU PRIO main-thread 0 26 rt-task1 1 86 rt-task3 1 91 rt-task4 1 85 1ms-polling-rt-task 1 94 rt-task2 2 85 rt-task5 2 92 rt-task6 2 92 rt-task7 2 85 rt-task8 2 85 rt-task13 2 90 rt-task15 2 85 kernel-drv-task11 2 98 kernel-drv-task10 3 94 kernel-drv-task12 3 98 kernel-drv-task14 3 98 perf record -e cobalt_core:cobalt_schedule swapper 0 [001] 99058.149903: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.149905: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.149930: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.149932: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150029: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150031: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150034: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150035: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150036: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150037: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150052: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150055: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150073: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150075: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150078: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150079: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150127: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150131: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150147: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150148: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150149: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.150150: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150184: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150185: cobalt_core:cobalt_schedule: status=0x10000000 t-task3 56485 [001] 99058.150186: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150187: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150202: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150205: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150246: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150248: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150334: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150335: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150336: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150337: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150345: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150347: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150352: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150355: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.150366: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150372: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150374: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150376: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150378: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150381: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150383: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.150387: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150444: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150446: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150447: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.150448: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150484: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150485: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150486: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150487: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150502: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150504: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.150517: cobalt_core:cobalt_schedule: status=0x10000000 main-thread 24485 [002] 99058.150543: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150544: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150564: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.150567: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150611: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150613: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150630: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150632: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150634: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150635: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150636: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150637: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150642: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150643: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150671: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150673: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150675: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150677: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150740: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150742: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150745: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.150747: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150761: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150763: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150783: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150785: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150786: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150787: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150839: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150841: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150879: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150881: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150911: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150913: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150933: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150934: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150935: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150936: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150938: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150940: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150970: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150971: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150974: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150975: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.151037: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.151039: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.151044: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.151046: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.151060: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.151063: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.151082: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.151084: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.151085: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.151086: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.151138: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.151143: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.151147: cobalt_core:cobalt_schedule: status=0x10000000 (---schedule delay 15ms---) swapper 0 [003] 99058.167775: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.167776: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167777: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.167792: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167794: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.167795: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task12 24088 [003] 99058.167797: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167798: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167801: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.167803: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.167804: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.167805: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.167807: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167808: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167809: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.167810: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167811: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167816: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.167817: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167824: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167826: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167827: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.167828: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167829: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167833: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.167834: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167843: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.167893: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167894: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.167896: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.167897: cobalt_core:cobalt_schedule: status=0x10000000 rt-task15 56598 [002] 99058.167898: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167906: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167921: cobalt_core:cobalt_schedule: status=0x10000000 rt-task15 56598 [002] 99058.167933: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.167934: cobalt_core:cobalt_schedule: status=0x10000000 main-thread 24483 [001] 99058.167945: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167948: cobalt_core:cobalt_schedule: status=0x10000000 main-thread 56538 [003] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167952: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167953: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167954: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167956: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.167960: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.167962: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167968: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task14 24083 [003] 99058.167976: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task14 24083 [003] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task12 24088 [003] 99058.167989: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167990: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167993: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167996: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.167997: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task14 24083 [003] 99058.168000: cobalt_core:cobalt_schedule: status=0x10000000 [-- Attachment #2: schedule_delay.txt --] [-- Type: text/plain, Size: 15336 bytes --] Thread-name CPU PRIO main-thread 0 26 rt-task1 1 86 rt-task3 1 91 rt-task4 1 85 1ms-polling-rt-task 1 94 rt-task2 2 85 rt-task5 2 92 rt-task6 2 92 rt-task7 2 85 rt-task8 2 85 rt-task13 2 90 rt-task15 2 85 kernel-drv-task11 2 98 kernel-drv-task10 3 94 kernel-drv-task12 3 98 kernel-drv-task14 3 98 perf record -e cobalt_core:cobalt_schedule swapper 0 [001] 99058.149903: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.149905: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.149930: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.149932: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150029: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150031: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150034: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150035: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150036: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150037: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150052: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150055: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150073: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150075: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150078: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150079: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150127: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150131: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150147: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150148: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150149: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.150150: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150184: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150185: cobalt_core:cobalt_schedule: status=0x10000000 t-task3 56485 [001] 99058.150186: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150187: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150202: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150205: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150246: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150248: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150334: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150335: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150336: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150337: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150345: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150347: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150352: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150355: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.150366: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150372: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150374: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150376: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150378: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150381: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150383: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.150387: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150444: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150446: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150447: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.150448: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150484: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150485: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150486: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150487: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150502: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150504: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.150517: cobalt_core:cobalt_schedule: status=0x10000000 main-thread 24485 [002] 99058.150543: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150544: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150564: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.150567: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150611: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150613: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150630: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150632: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150634: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150635: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150636: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150637: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150642: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150643: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150671: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150673: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150675: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150677: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150740: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150742: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150745: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.150747: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150761: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150763: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150783: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150785: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150786: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150787: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150839: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150841: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150879: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.150881: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150911: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.150913: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.150933: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150934: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.150935: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.150936: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150938: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.150940: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150970: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.150971: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.150974: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.150975: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.151037: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.151039: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.151044: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.151046: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.151060: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.151063: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.151082: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.151084: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.151085: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.151086: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.151138: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.151143: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.151147: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.167775: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.167776: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167777: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.167792: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167794: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.167795: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task12 24088 [003] 99058.167797: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167798: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167801: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 56510 [002] 99058.167803: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.167804: cobalt_core:cobalt_schedule: status=0x10000000 rt-task6 56507 [002] 99058.167805: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.167807: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167808: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167809: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.167810: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167811: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167816: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.167817: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167824: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167826: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167827: cobalt_core:cobalt_schedule: status=0x10000000 rt-task8 56496 [002] 99058.167828: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167829: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167833: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 99058.167834: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167843: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.167893: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167894: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 56499 [002] 99058.167896: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-rt-task 56488 [001] 99058.167897: cobalt_core:cobalt_schedule: status=0x10000000 rt-task15 56598 [002] 99058.167898: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167906: cobalt_core:cobalt_schedule: status=0x10000000 rt-task13 56506 [002] 99058.167921: cobalt_core:cobalt_schedule: status=0x10000000 rt-task15 56598 [002] 99058.167933: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 56508 [002] 99058.167934: cobalt_core:cobalt_schedule: status=0x10000000 main-thread 24483 [001] 99058.167945: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167948: cobalt_core:cobalt_schedule: status=0x10000000 main-thread 56538 [003] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167952: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167953: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167954: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 56485 [001] 99058.167956: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 56487 [001] 99058.167960: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 56486 [001] 99058.167962: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167968: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task14 24083 [003] 99058.167976: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task14 24083 [003] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task12 24088 [003] 99058.167989: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 24077 [002] 99058.167990: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 99058.167993: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task10 24070 [003] 99058.167996: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 99058.167997: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task14 24083 [003] 99058.168000: cobalt_core:cobalt_schedule: status=0x10000000 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: schedule delay 15ms 2025-11-12 6:09 schedule delay 15ms JerryJun @ 2025-11-12 8:23 ` Jan Kiszka 2025-11-13 4:00 ` JerryJun 0 siblings, 1 reply; 11+ messages in thread From: Jan Kiszka @ 2025-11-12 8:23 UTC (permalink / raw) To: JerryJun, xenomai@lists.linux.dev On 12.11.25 07:09, JerryJun wrote: > > hi： > We are encountering some scheduling issues. Within a 15ms time interval (99058.151147 -> 99058.167775), no real-time threads were scheduled, > including the swapper idle thread. We have a 1ms-polling-rt-task running on CPU1, but it was also not scheduled during this period. > Even the RTDM interrupts from peripherals were not responded to or processed. What could be the reason for this? > > Architecture： x86_64 > linux kernel：5.10.199-dovetail1 This version is 2 years old. Did you also check if the latest release (v5.10.245-cip65-dovetail1) has this issue? > cobalt：3.2.4 > kernel cmdline: xenomai.supported_cpus=0xf idle=halt nosmap > > Thread-name CPU PRIO > main-thread 0 26 > rt-task1 1 86 > rt-task3 1 91 > rt-task4 1 85 > 1ms-polling-rt-task 1 94 > rt-task2 2 85 > rt-task5 2 92 > rt-task6 2 92 > rt-task7 2 85 > rt-task8 2 85 > rt-task13 2 90 > rt-task15 2 85 > kernel-drv-task11 2 98 > kernel-drv-task10 3 94 > kernel-drv-task12 3 98 > kernel-drv-task14 3 98 > > perf record -e cobalt_core:cobalt_schedule > > swapper 0 [001] 99058.149903: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.149905: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.149930: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.149932: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150029: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150031: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150034: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150035: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150036: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150037: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150052: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150055: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150073: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task5 56510 [002] 99058.150075: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150078: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task6 56507 [002] 99058.150079: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150127: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.150131: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.150147: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.150148: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150149: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task8 56496 [002] 99058.150150: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150184: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150185: cobalt_core:cobalt_schedule: status=0x10000000 > t-task3 56485 [001] 99058.150186: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150187: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150202: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150205: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150246: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150248: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150334: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150335: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150336: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150337: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150345: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150347: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150352: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150355: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [003] 99058.150366: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150372: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task5 56510 [002] 99058.150374: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150376: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task6 56507 [002] 99058.150378: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150381: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.150383: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.150387: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150444: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150446: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150447: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task8 56496 [002] 99058.150448: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150484: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150485: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150486: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150487: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150502: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150504: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [003] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.150517: cobalt_core:cobalt_schedule: status=0x10000000 > main-thread 24485 [002] 99058.150543: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150544: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150564: cobalt_core:cobalt_schedule: status=0x10000000 > 1ms-polling-rt-task 56488 [001] 99058.150567: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150611: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150613: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150630: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.150632: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150634: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150635: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150636: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150637: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150642: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150643: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150671: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task5 56510 [002] 99058.150673: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150675: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task6 56507 [002] 99058.150677: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150740: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150742: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150745: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task8 56496 [002] 99058.150747: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150761: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150763: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150783: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150785: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150786: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150787: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150839: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150841: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150879: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.150881: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150911: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.150913: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.150933: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150934: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.150935: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.150936: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150938: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.150940: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150970: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task5 56510 [002] 99058.150971: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.150974: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task6 56507 [002] 99058.150975: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.151037: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.151039: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.151044: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task8 56496 [002] 99058.151046: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.151060: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.151063: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.151082: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.151084: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.151085: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.151086: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.151138: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.151143: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.151147: cobalt_core:cobalt_schedule: status=0x10000000 > (---schedule delay 15ms---) > swapper 0 [003] 99058.167775: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.167776: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.167777: cobalt_core:cobalt_schedule: status=0x10000000 > 1ms-polling-rt-task 56488 [001] 99058.167792: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task11 24077 [002] 99058.167794: cobalt_core:cobalt_schedule: status=0x10000000 > 1ms-polling-rt-task 56488 [001] 99058.167795: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task12 24088 [003] 99058.167797: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167798: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task11 24077 [002] 99058.167801: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task5 56510 [002] 99058.167803: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.167804: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task6 56507 [002] 99058.167805: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.167807: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167808: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167809: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.167810: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167811: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167816: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [003] 99058.167817: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167824: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167826: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167827: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task8 56496 [002] 99058.167828: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167829: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167833: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [003] 99058.167834: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167843: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.167893: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167894: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task7 56499 [002] 99058.167896: cobalt_core:cobalt_schedule: status=0x10000000 > 1ms-polling-rt-task 56488 [001] 99058.167897: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task15 56598 [002] 99058.167898: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167906: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task13 56506 [002] 99058.167921: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task15 56598 [002] 99058.167933: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task2 56508 [002] 99058.167934: cobalt_core:cobalt_schedule: status=0x10000000 > main-thread 24483 [001] 99058.167945: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167948: cobalt_core:cobalt_schedule: status=0x10000000 > main-thread 56538 [003] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167952: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167953: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167954: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task3 56485 [001] 99058.167956: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task1 56487 [001] 99058.167960: cobalt_core:cobalt_schedule: status=0x10000000 > rt-task4 56486 [001] 99058.167962: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task11 24077 [002] 99058.167968: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task14 24083 [003] 99058.167976: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task14 24083 [003] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task12 24088 [003] 99058.167989: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task11 24077 [002] 99058.167990: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [002] 99058.167993: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task10 24070 [003] 99058.167996: cobalt_core:cobalt_schedule: status=0x10000000 > swapper 0 [001] 99058.167997: cobalt_core:cobalt_schedule: status=0x10000000 > kernel-drv-task14 24083 [003] 99058.168000: cobalt_core:cobalt_schedule: status=0x10000000 > For a deeper analysis, it would be good to trace all cobalt* and all irq* events. Those may tell us if we are not getting irqs at all or if something is blocking their processing. Jan -- Siemens AG, Foundational Technologies Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re:Re: schedule delay 15ms 2025-11-12 8:23 ` Jan Kiszka @ 2025-11-13 4:00 ` JerryJun 2025-11-13 5:31 ` Jan Kiszka 0 siblings, 1 reply; 11+ messages in thread From: JerryJun @ 2025-11-13 4:00 UTC (permalink / raw) To: Jan Kiszka, xenomai@lists.linux.dev [-- Attachment #1: Type: text/plain, Size: 17203 bytes --] We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 At 2025-11-12 16:23:03, "Jan Kiszka" wrote: >On 12.11.25 07:09, JerryJun wrote: >> >> hi： >> We are encountering some scheduling issues. Within a 15ms time interval (99058.151147 -> 99058.167775), no real-time threads were scheduled, >> including the swapper idle thread. We have a 1ms-polling-rt-task running on CPU1, but it was also not scheduled during this period. >> Even the RTDM interrupts from peripherals were not responded to or processed. What could be the reason for this? >> >> Architecture： x86_64 >> linux kernel：5.10.199-dovetail1 > >This version is 2 years old. Did you also check if the latest release >(v5.10.245-cip65-dovetail1) has this issue? > >> cobalt：3.2.4 >> kernel cmdline: xenomai.supported_cpus=0xf idle=halt nosmap >> >> Thread-name CPU PRIO >> main-thread 0 26 >> rt-task1 1 86 >> rt-task3 1 91 >> rt-task4 1 85 >> 1ms-polling-rt-task 1 94 >> rt-task2 2 85 >> rt-task5 2 92 >> rt-task6 2 92 >> rt-task7 2 85 >> rt-task8 2 85 >> rt-task13 2 90 >> rt-task15 2 85 >> kernel-drv-task11 2 98 >> kernel-drv-task10 3 94 >> kernel-drv-task12 3 98 >> kernel-drv-task14 3 98 >> >> perf record -e cobalt_core:cobalt_schedule >> >> swapper 0 [001] 99058.149903: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.149905: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.149930: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.149932: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150029: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150031: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150034: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150035: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150036: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150037: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150052: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150055: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150073: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task5 56510 [002] 99058.150075: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150078: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task6 56507 [002] 99058.150079: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150127: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.150131: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.150147: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.150148: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150149: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task8 56496 [002] 99058.150150: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150184: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150185: cobalt_core:cobalt_schedule: status=0x10000000 >> t-task3 56485 [001] 99058.150186: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150187: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150202: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150205: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150246: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150248: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150334: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150335: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150336: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150337: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150345: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150347: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150352: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150355: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [003] 99058.150366: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150372: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task5 56510 [002] 99058.150374: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150376: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task6 56507 [002] 99058.150378: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150381: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.150383: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.150387: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150444: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150446: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150447: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task8 56496 [002] 99058.150448: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150484: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150485: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150486: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150487: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150502: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150504: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [003] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150505: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.150517: cobalt_core:cobalt_schedule: status=0x10000000 >> main-thread 24485 [002] 99058.150543: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150544: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150564: cobalt_core:cobalt_schedule: status=0x10000000 >> 1ms-polling-rt-task 56488 [001] 99058.150567: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150611: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150613: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150630: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.150632: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150634: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150635: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150636: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150637: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150642: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150643: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150671: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task5 56510 [002] 99058.150673: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150675: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task6 56507 [002] 99058.150677: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150740: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150742: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150745: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task8 56496 [002] 99058.150747: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150761: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150763: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150783: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150785: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150786: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150787: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150839: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150841: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150879: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.150881: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150911: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.150913: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.150933: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150934: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.150935: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.150936: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150938: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.150940: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150970: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task5 56510 [002] 99058.150971: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.150974: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task6 56507 [002] 99058.150975: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.151037: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.151039: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.151044: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task8 56496 [002] 99058.151046: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.151060: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.151063: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.151082: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.151084: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.151085: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.151086: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.151138: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.151143: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.151147: cobalt_core:cobalt_schedule: status=0x10000000 >> (---schedule delay 15ms---) >> swapper 0 [003] 99058.167775: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.167776: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.167777: cobalt_core:cobalt_schedule: status=0x10000000 >> 1ms-polling-rt-task 56488 [001] 99058.167792: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task11 24077 [002] 99058.167794: cobalt_core:cobalt_schedule: status=0x10000000 >> 1ms-polling-rt-task 56488 [001] 99058.167795: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task12 24088 [003] 99058.167797: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167798: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task11 24077 [002] 99058.167801: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task5 56510 [002] 99058.167803: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.167804: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task6 56507 [002] 99058.167805: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.167807: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167808: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167809: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.167810: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167811: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167816: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [003] 99058.167817: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167824: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167826: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167827: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task8 56496 [002] 99058.167828: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167829: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167833: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [003] 99058.167834: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167843: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.167893: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167894: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task7 56499 [002] 99058.167896: cobalt_core:cobalt_schedule: status=0x10000000 >> 1ms-polling-rt-task 56488 [001] 99058.167897: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task15 56598 [002] 99058.167898: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167906: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task13 56506 [002] 99058.167921: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task15 56598 [002] 99058.167933: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task2 56508 [002] 99058.167934: cobalt_core:cobalt_schedule: status=0x10000000 >> main-thread 24483 [001] 99058.167945: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167948: cobalt_core:cobalt_schedule: status=0x10000000 >> main-thread 56538 [003] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167950: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167952: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167953: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167954: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167955: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task3 56485 [001] 99058.167956: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task1 56487 [001] 99058.167960: cobalt_core:cobalt_schedule: status=0x10000000 >> rt-task4 56486 [001] 99058.167962: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task11 24077 [002] 99058.167968: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task14 24083 [003] 99058.167976: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task14 24083 [003] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.167977: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task12 24088 [003] 99058.167989: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task11 24077 [002] 99058.167990: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [002] 99058.167993: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task10 24070 [003] 99058.167996: cobalt_core:cobalt_schedule: status=0x10000000 >> swapper 0 [001] 99058.167997: cobalt_core:cobalt_schedule: status=0x10000000 >> kernel-drv-task14 24083 [003] 99058.168000: cobalt_core:cobalt_schedule: status=0x10000000 >> > >For a deeper analysis, it would be good to trace all cobalt* and all >irq* events. Those may tell us if we are not getting irqs at all or if >something is blocking their processing. > >Jan > >-- >Siemens AG, Foundational Technologies >Linux Expert Center [-- Attachment #2: schedule-delay.txt --] [-- Type: text/plain, Size: 33451 bytes --] swapper 0 [002] 7174.313272: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task2 3170 [002] 7174.313273: cobalt_core:cobalt_trace_pid: pid=3170, prio=85 swapper 0 [000] 7174.313273: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096a458 swapper 0 [000] 7174.313274: cobalt_core:cobalt_synch_wakeup: synch=0xffffc9000096a540 swapper 0 [000] 7174.313274: cobalt_core:cobalt_thread_resume: name=sampling-10721 pid=10724 mask=0x2 swapper 0 [000] 7174.313274: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 swapper 0 [000] 7174.313275: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 3170 [002] 7174.313275: cobalt_core:cobalt_thread_suspend: pid=3170 mask=0x4 timeout=7174288833545 timeout_mode=1 wchan=(nil) rt-task2 3170 [002] 7174.313275: cobalt_core:cobalt_timer_start: timer=0xffffc9000096eef0(MAIN-TASK) value=7174288833545 interval=0 mode=0x1 rt-task2 3170 [002] 7174.313275: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 3170 [002] 7174.313276: cobalt_core:cobalt_trace_pid: pid=3170, prio=85 rt-task2 3170 [002] 7174.313276: cobalt_core:cobalt_switch_context: prev_name=rt-task2tor prev_pid=3170 prev_prio=85 prev_state=0x48044 ==> next_name=ROOT/2 next_pid=0 next_prio=-1 rt-task2 3170 [002] 7174.313276: cobalt_core:cobalt_timer_stop: timer=0xffff888470136828 swapper 0 [002] 7174.313277: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [000] 7174.313277: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [000] 7174.313278: cobalt_core:cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=sampling-10721 next_pid=10724 next_prio=99 swapper 0 [000] 7174.313278: cobalt_core:cobalt_timer_start: timer=0xffff888470036828([watchdog]) value=1000000000 interval=0 mode=0x0 swapper 0 [001] 7174.313279: irq:irq_pipeline_entry: irq=33027 sampling-10721 10724 [000] 7174.313279: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 swapper 0 [001] 7174.313279: cobalt_core:cobalt_timer_expire: timer=0xffffc90000977ef0 swapper 0 [001] 7174.313280: cobalt_core:cobalt_thread_resume: name=rt-task1 pid=3147 mask=0x4 swapper 0 [001] 7174.313280: cobalt_core:cobalt_trace_pid: pid=3147, prio=86 swapper 0 [001] 7174.313280: cobalt_core:cobalt_timer_stop: timer=0xffffc90000977ef0 swapper 0 [001] 7174.313281: cobalt_core:cobalt_schedule: status=0x10000000 sampling-10721 10724 [000] 7174.313281: cobalt_core:cobalt_synch_sleepon: synch=0xffffc9000096a540 sampling-10721 10724 [000] 7174.313281: cobalt_core:cobalt_thread_suspend: pid=10724 mask=0x2 timeout=0 timeout_mode=0 wchan=0xffffc9000096a540 sampling-10721 10724 [000] 7174.313281: cobalt_core:cobalt_schedule: status=0x10000000 sampling-10721 10724 [000] 7174.313282: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 sampling-10721 10724 [000] 7174.313282: cobalt_core:cobalt_switch_context: prev_name=sampling-10721 prev_pid=10724 prev_prio=99 prev_state=0x4c042 ==> next_name=ROOT/0 next_pid=0 next_prio=-1 sampling-10721 10724 [000] 7174.313282: cobalt_core:cobalt_timer_stop: timer=0xffff888470036828 swapper 0 [000] 7174.313283: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 7174.313283: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 7174.313284: cobalt_core:cobalt_switch_context: prev_name=ROOT/1 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task1 next_pid=3147 next_prio=86 swapper 0 [001] 7174.313284: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task1 3147 [001] 7174.313285: cobalt_core:cobalt_trace_pid: pid=3147, prio=86 rt-task1 3147 [001] 7174.313287: cobalt_core:cobalt_thread_suspend: pid=3147 mask=0x4 timeout=7174288896564 timeout_mode=1 wchan=(nil) rt-task1 3147 [001] 7174.313287: cobalt_core:cobalt_timer_start: timer=0xffffc90000977ef0(MAIN-TASK) value=7174288896564 interval=0 mode=0x1 rt-task1 3147 [001] 7174.313287: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 3147 [001] 7174.313288: cobalt_core:cobalt_trace_pid: pid=3147, prio=86 rt-task1 3147 [001] 7174.313288: cobalt_core:cobalt_switch_context: prev_name=rt-task1 prev_pid=3147 prev_prio=86 prev_state=0x48044 ==> next_name=ROOT/1 next_pid=0 next_prio=-1 rt-task1 3147 [001] 7174.313289: cobalt_core:cobalt_timer_stop: timer=0xffff8884700b6828 swapper 0 [001] 7174.313289: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [003] 7174.313300: irq:irq_pipeline_entry: irq=33027 swapper 0 [003] 7174.313301: cobalt_core:cobalt_timer_expire: timer=0xffff8884701b6298 swapper 0 [003] 7174.313305: cobalt_core:cobalt_timer_start: timer=0xffff8884701b6298([host-timer/3]) value=83456 interval=0 mode=0x0 swapper 0 [001] 7174.313309: irq:irq_pipeline_entry: irq=33027 swapper 0 [001] 7174.313309: cobalt_core:cobalt_timer_expire: timer=0xffff8884700b6298 swapper 0 [001] 7174.313311: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6298([host-timer/1]) value=194701 interval=0 mode=0x0 swapper 0 [002] 7174.313360: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 7174.313361: cobalt_core:cobalt_timer_expire: timer=0xffffc900009736f0 swapper 0 [002] 7174.313361: cobalt_core:cobalt_thread_resume: name=rt-task7 or pid=3161 mask=0x4 swapper 0 [002] 7174.313361: cobalt_core:cobalt_trace_pid: pid=3161, prio=85 swapper 0 [002] 7174.313362: cobalt_core:cobalt_timer_stop: timer=0xffffc900009736f0 swapper 0 [002] 7174.313362: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 7174.313362: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 7174.313363: cobalt_core:cobalt_switch_context: prev_name=ROOT/2 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task7 or next_pid=3161 next_prio=85 swapper 0 [001] 7174.313363: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 7174.313363: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task7 3161 [002] 7174.313364: cobalt_core:cobalt_trace_pid: pid=3161, prio=85 swapper 0 [001] 7174.313364: cobalt_core:cobalt_timer_expire: timer=0xffffc90000979cf0 swapper 0 [001] 7174.313365: cobalt_core:cobalt_thread_resume: name=rt-task3 pid=3145 mask=0x4 swapper 0 [001] 7174.313365: cobalt_core:cobalt_trace_pid: pid=3145, prio=91 swapper 0 [001] 7174.313365: cobalt_core:cobalt_timer_stop: timer=0xffffc90000979cf0 swapper 0 [001] 7174.313365: cobalt_core:cobalt_synch_forget: synch=0xffffc9000097ab08 rt-task7 3161 [002] 7174.313366: cobalt_core:cobalt_thread_suspend: pid=3161 mask=0x4 timeout=7174289074552 timeout_mode=1 wchan=(nil) swapper 0 [001] 7174.313366: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 3161 [002] 7174.313366: cobalt_core:cobalt_timer_start: timer=0xffffc900009736f0(MAIN-TASK) value=7174289074552 interval=0 mode=0x1 rt-task7 3161 [002] 7174.313367: cobalt_core:cobalt_schedule: status=0x10000000 rt-task7 3161 [002] 7174.313367: cobalt_core:cobalt_trace_pid: pid=3161, prio=85 rt-task7 3161 [002] 7174.313367: cobalt_core:cobalt_switch_context: prev_name=rt-task7 or prev_pid=3161 prev_prio=85 prev_state=0x48044 ==> next_name=ROOT/2 next_pid=0 next_prio=-1 rt-task7 3161 [002] 7174.313368: cobalt_core:cobalt_timer_stop: timer=0xffff888470136828 swapper 0 [002] 7174.313368: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 7174.313369: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 7174.313369: cobalt_core:cobalt_switch_context: prev_name=ROOT/1 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task3 next_pid=3145 next_prio=91 swapper 0 [001] 7174.313369: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task3 3145 [001] 7174.313370: cobalt_core:cobalt_trace_pid: pid=3145, prio=91 swapper 0 [002] 7174.313371: irq:irq_pipeline_entry: irq=33027 rt-task3 3145 [001] 7174.313371: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 7174.313371: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096eef0 swapper 0 [002] 7174.313371: cobalt_core:cobalt_thread_resume: name=rt-task2tor pid=3170 mask=0x4 swapper 0 [002] 7174.313372: cobalt_core:cobalt_trace_pid: pid=3170, prio=85 swapper 0 [000] 7174.313372: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 7174.313372: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096eef0 swapper 0 [002] 7174.313372: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 3145 [001] 7174.313372: cobalt_core:cobalt_timer_expire: timer=0xffffc90000978ef0 rt-task3 3145 [001] 7174.313373: cobalt_core:cobalt_thread_resume: name=rt-task476 pid=3146 mask=0x4 rt-task3 3145 [001] 7174.313373: cobalt_core:cobalt_trace_pid: pid=3146, prio=85 rt-task3 3145 [001] 7174.313373: cobalt_core:cobalt_timer_stop: timer=0xffffc90000978ef0 rt-task3 3145 [001] 7174.313374: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [000] 7174.313374: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096a458 swapper 0 [000] 7174.313374: cobalt_core:cobalt_synch_wakeup: synch=0xffffc9000096a540 swapper 0 [000] 7174.313374: cobalt_core:cobalt_thread_resume: name=sampling-10721 pid=10724 mask=0x2 swapper 0 [000] 7174.313375: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 swapper 0 [000] 7174.313375: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 7174.313375: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 7174.313376: cobalt_core:cobalt_switch_context: prev_name=ROOT/2 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task2tor next_pid=3170 next_prio=85 swapper 0 [002] 7174.313376: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task2 3170 [002] 7174.313377: cobalt_core:cobalt_trace_pid: pid=3170, prio=85 rt-task3 3145 [001] 7174.313377: cobalt_core:cobalt_trace_pid: pid=3145, prio=91 swapper 0 [000] 7174.313378: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [000] 7174.313378: cobalt_core:cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=sampling-10721 next_pid=10724 next_prio=99 swapper 0 [000] 7174.313379: cobalt_core:cobalt_timer_start: timer=0xffff888470036828([watchdog]) value=1000000000 interval=0 mode=0x0 sampling-10721 10724 [000] 7174.313379: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 rt-task2 3170 [002] 7174.313380: cobalt_core:cobalt_thread_suspend: pid=3170 mask=0x4 timeout=7174288937443 timeout_mode=1 wchan=(nil) rt-task2 3170 [002] 7174.313380: cobalt_core:cobalt_timer_start: timer=0xffffc9000096eef0(MAIN-TASK) value=7174288937443 interval=0 mode=0x1 rt-task2 3170 [002] 7174.313381: cobalt_core:cobalt_schedule: status=0x10000000 rt-task2 3170 [002] 7174.313381: cobalt_core:cobalt_trace_pid: pid=3170, prio=85 rt-task2 3170 [002] 7174.313381: cobalt_core:cobalt_switch_context: prev_name=rt-task2tor prev_pid=3170 prev_prio=85 prev_state=0x48044 ==> next_name=ROOT/2 next_pid=0 next_prio=-1 rt-task2 3170 [002] 7174.313382: cobalt_core:cobalt_timer_stop: timer=0xffff888470136828 swapper 0 [002] 7174.313382: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 rt-task3 3145 [001] 7174.313383: cobalt_core:cobalt_synch_acquire: synch=0xffffc9000097a908 sampling-10721 10724 [000] 7174.313383: cobalt_core:cobalt_synch_sleepon: synch=0xffffc9000096a540 sampling-10721 10724 [000] 7174.313384: cobalt_core:cobalt_thread_suspend: pid=10724 mask=0x2 timeout=0 timeout_mode=0 wchan=0xffffc9000096a540 sampling-10721 10724 [000] 7174.313384: cobalt_core:cobalt_schedule: status=0x10000000 sampling-10721 10724 [000] 7174.313384: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 sampling-10721 10724 [000] 7174.313385: cobalt_core:cobalt_switch_context: prev_name=sampling-10721 prev_pid=10724 prev_prio=99 prev_state=0x4c042 ==> next_name=ROOT/0 next_pid=0 next_prio=-1 sampling-10721 10724 [000] 7174.313385: cobalt_core:cobalt_timer_stop: timer=0xffff888470036828 swapper 0 [000] 7174.313386: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 rt-task3 3145 [001] 7174.313386: cobalt_core:cobalt_synch_release: synch=0xffffc9000097a908 rt-task3 3145 [001] 7174.313386: cobalt_core:cobalt_synch_sleepon: synch=0xffffc9000097ab08 rt-task3 3145 [001] 7174.313387: cobalt_core:cobalt_thread_suspend: pid=3145 mask=0x2 timeout=7174288993625 timeout_mode=1 wchan=0xffffc9000097ab08 rt-task3 3145 [001] 7174.313387: cobalt_core:cobalt_timer_start: timer=0xffffc90000979cf0(MAIN-TASK) value=7174288993625 interval=0 mode=0x1 rt-task3 3145 [001] 7174.313387: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 3145 [001] 7174.313388: cobalt_core:cobalt_trace_pid: pid=3145, prio=91 rt-task3 3145 [001] 7174.313388: cobalt_core:cobalt_switch_context: prev_name=rt-task3 prev_pid=3145 prev_prio=91 prev_state=0x48046 ==> next_name=rt-task476 next_pid=3146 next_prio=85 rt-task4 3146 [001] 7174.313389: cobalt_core:cobalt_trace_pid: pid=3146, prio=85 swapper 0 [003] 7174.313389: irq:irq_pipeline_entry: irq=33027 rt-task4 3146 [001] 7174.313390: cobalt_core:cobalt_thread_suspend: pid=3146 mask=0x4 timeout=7174288999408 timeout_mode=1 wchan=(nil) rt-task4 3146 [001] 7174.313390: cobalt_core:cobalt_timer_start: timer=0xffffc90000978ef0(MAIN-TASK) value=7174288999408 interval=0 mode=0x1 rt-task4 3146 [001] 7174.313390: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 3146 [001] 7174.313391: cobalt_core:cobalt_trace_pid: pid=3146, prio=85 rt-task4 3146 [001] 7174.313391: cobalt_core:cobalt_switch_context: prev_name=rt-task476 prev_pid=3146 prev_prio=85 prev_state=0x48044 ==> next_name=ROOT/1 next_pid=0 next_prio=-1 rt-task4 3146 [001] 7174.313391: cobalt_core:cobalt_timer_stop: timer=0xffff8884700b6828 swapper 0 [001] 7174.313392: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [003] 7174.313392: cobalt_core:cobalt_timer_expire: timer=0xffff8884701b6298 swapper 0 [003] 7174.313396: cobalt_core:cobalt_timer_start: timer=0xffff8884701b6298([host-timer/3]) value=84197 interval=0 mode=0x0 swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 swapper 0 [000] 7174.323087: irq:irq_pipeline_entry: irq=33027 swapper 0 [001] 7174.323087: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 7174.323087: irq:irq_pipeline_entry: irq=33027 swapper 0 [003] 7174.323087: cobalt_core:cobalt_timer_expire: timer=0xffffffffa0a546b8 swapper 0 [003] 7174.323088: cobalt_core:cobalt_thread_resume: name=kernel-drv-task11 pid=2456 mask=0x4 swapper 0 [003] 7174.323088: cobalt_core:cobalt_trace_pid: pid=2456, prio=94 swapper 0 [003] 7174.323088: cobalt_core:cobalt_timer_stop: timer=0xffffffffa0a546b8 swapper 0 [003] 7174.323088: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0a549e8 swapper 0 [003] 7174.323089: cobalt_core:cobalt_timer_expire: timer=0xffff8884701b6298 swapper 0 [000] 7174.323089: cobalt_core:cobalt_timer_expire: timer=0xffff888470036298 swapper 0 [003] 7174.323089: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [000] 7174.323090: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096a458 swapper 0 [000] 7174.323090: cobalt_core:cobalt_synch_wakeup: synch=0xffffc9000096a540 swapper 0 [000] 7174.323090: cobalt_core:cobalt_thread_resume: name=sampling-10721 pid=10724 mask=0x2 swapper 0 [000] 7174.323090: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 swapper 0 [000] 7174.323091: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 7174.323091: cobalt_core:cobalt_timer_expire: timer=0xffffc90000977ef0 swapper 0 [001] 7174.323092: cobalt_core:cobalt_thread_resume: name=rt-task1 pid=3147 mask=0x4 swapper 0 [001] 7174.323092: cobalt_core:cobalt_trace_pid: pid=3147, prio=86 swapper 0 [001] 7174.323092: cobalt_core:cobalt_timer_stop: timer=0xffffc90000977ef0 swapper 0 [001] 7174.323092: cobalt_core:cobalt_timer_expire: timer=0xffff8884700b6298 swapper 0 [001] 7174.323093: cobalt_core:cobalt_timer_expire: timer=0xffffc90000979cf0 swapper 0 [001] 7174.323093: cobalt_core:cobalt_thread_resume: name=rt-task3 pid=3145 mask=0x4 swapper 0 [001] 7174.323093: cobalt_core:cobalt_trace_pid: pid=3145, prio=91 swapper 0 [001] 7174.323093: cobalt_core:cobalt_timer_stop: timer=0xffffc90000979cf0 swapper 0 [001] 7174.323094: cobalt_core:cobalt_synch_forget: synch=0xffffc9000097ab08 swapper 0 [001] 7174.323094: cobalt_core:cobalt_timer_expire: timer=0xffffc90000978ef0 swapper 0 [001] 7174.323094: cobalt_core:cobalt_thread_resume: name=rt-task476 pid=3146 mask=0x4 swapper 0 [001] 7174.323095: cobalt_core:cobalt_trace_pid: pid=3146, prio=85 swapper 0 [001] 7174.323095: cobalt_core:cobalt_timer_stop: timer=0xffffc90000978ef0 swapper 0 [001] 7174.323095: cobalt_core:cobalt_timer_expire: timer=0xffffc900009770f0 swapper 0 [001] 7174.323095: cobalt_core:cobalt_thread_resume: name=1ms-polling-task76 pid=3148 mask=0x4 swapper 0 [001] 7174.323096: cobalt_core:cobalt_trace_pid: pid=3148, prio=93 swapper 0 [001] 7174.323096: cobalt_core:cobalt_timer_stop: timer=0xffffc900009770f0 swapper 0 [001] 7174.323096: cobalt_core:cobalt_timer_expire: timer=0xffffc900009752f0 swapper 0 [001] 7174.323097: cobalt_core:cobalt_thread_resume: name=rt-task20076 pid=3150 mask=0x4 swapper 0 [001] 7174.323097: cobalt_core:cobalt_trace_pid: pid=3150, prio=93 swapper 0 [001] 7174.323097: cobalt_core:cobalt_timer_stop: timer=0xffffc900009752f0 swapper 0 [001] 7174.323097: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0a83d80 swapper 0 [002] 7174.323098: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096eef0 swapper 0 [001] 7174.323098: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 7174.323098: cobalt_core:cobalt_thread_resume: name=rt-task2tor pid=3170 mask=0x4 swapper 0 [002] 7174.323099: cobalt_core:cobalt_trace_pid: pid=3170, prio=85 swapper 0 [002] 7174.323099: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096eef0 swapper 0 [002] 7174.323099: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096e0f0 swapper 0 [002] 7174.323099: cobalt_core:cobalt_thread_resume: name=rt-task5 pid=3172 mask=0x4 swapper 0 [002] 7174.323100: cobalt_core:cobalt_trace_pid: pid=3172, prio=92 swapper 0 [002] 7174.323100: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096e0f0 swapper 0 [002] 7174.323100: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096fcf0 swapper 0 [002] 7174.323100: cobalt_core:cobalt_thread_resume: name=rt-task6 pid=3169 mask=0x4 swapper 0 [002] 7174.323101: cobalt_core:cobalt_trace_pid: pid=3169, prio=92 swapper 0 [002] 7174.323101: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096fcf0 swapper 0 [002] 7174.323101: cobalt_core:cobalt_timer_expire: timer=0xffffc900009744f0 swapper 0 [002] 7174.323102: cobalt_core:cobalt_thread_resume: name=rt-task8 pid=3158 mask=0x4 swapper 0 [002] 7174.323102: cobalt_core:cobalt_trace_pid: pid=3158, prio=85 swapper 0 [002] 7174.323102: cobalt_core:cobalt_timer_stop: timer=0xffffc900009744f0 swapper 0 [002] 7174.323102: cobalt_core:cobalt_timer_expire: timer=0xffffc900009736f0 swapper 0 [002] 7174.323103: cobalt_core:cobalt_thread_resume: name=rt-task7 or pid=3161 mask=0x4 swapper 0 [002] 7174.323103: cobalt_core:cobalt_trace_pid: pid=3161, prio=85 swapper 0 [002] 7174.323103: cobalt_core:cobalt_timer_stop: timer=0xffffc900009736f0 swapper 0 [002] 7174.323103: cobalt_core:cobalt_timer_expire: timer=0xffff888470136298 swapper 0 [002] 7174.323104: cobalt_core:cobalt_timer_expire: timer=0xffffffffa0a83fe0 swapper 0 [002] 7174.323104: cobalt_core:cobalt_thread_resume: name=kernel-drv-task11 pid=2462 mask=0x4 swapper 0 [002] 7174.323104: cobalt_core:cobalt_trace_pid: pid=2462, prio=98 swapper 0 [002] 7174.323104: cobalt_core:cobalt_timer_stop: timer=0xffffffffa0a83fe0 swapper 0 [002] 7174.323105: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0a84310 swapper 0 [003] 7174.323105: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 7174.323105: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [003] 7174.323106: cobalt_core:cobalt_switch_context: prev_name=ROOT/3 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=kernel-drv-task11 next_pid=2456 next_prio=94 swapper 0 [003] 7174.323106: cobalt_core:cobalt_timer_start: timer=0xffff8884701b6828([watchdog]) value=1000000000 interval=0 mode=0x0 kernel-drv-task11 2456 [003] 7174.323107: cobalt_core:cobalt_trace_pid: pid=2456, prio=94 swapper 0 [000] 7174.323108: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [000] 7174.323108: cobalt_core:cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=sampling-10721 next_pid=10724 next_prio=99 swapper 0 [000] 7174.323109: cobalt_core:cobalt_timer_start: timer=0xffff888470036828([watchdog]) value=1000000000 interval=0 mode=0x0 sampling-10721 10724 [000] 7174.323110: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 swapper 0 [001] 7174.323110: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 7174.323111: cobalt_core:cobalt_switch_context: prev_name=ROOT/1 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=1ms-polling-task76 next_pid=3148 next_prio=93 swapper 0 [001] 7174.323111: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6828([watchdog]) value=1000000000 interval=0 mode=0x0 1ms-polling-task 3148 [001] 7174.323112: cobalt_core:cobalt_trace_pid: pid=3148, prio=93 swapper 0 [002] 7174.323113: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 1ms-polling-task 3148 [001] 7174.323113: irq:irq_pipeline_entry: irq=83 swapper 0 [002] 7174.323113: cobalt_core:cobalt_switch_context: prev_name=ROOT/2 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=kernel-drv-task11 next_pid=2462 next_prio=98 swapper 0 [002] 7174.323113: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 kernel-drv-task11 2462 [002] 7174.323114: cobalt_core:cobalt_trace_pid: pid=2462, prio=98 sampling-10721 10724 [000] 7174.323115: cobalt_core:cobalt_synch_sleepon: synch=0xffffc9000096a540 sampling-10721 10724 [000] 7174.323115: cobalt_core:cobalt_thread_suspend: pid=10724 mask=0x2 timeout=0 timeout_mode=0 wchan=0xffffc9000096a540 sampling-10721 10724 [000] 7174.323116: cobalt_core:cobalt_schedule: status=0x10000000 sampling-10721 10724 [000] 7174.323116: cobalt_core:cobalt_trace_pid: pid=10724, prio=99 sampling-10721 10724 [000] 7174.323116: cobalt_core:cobalt_switch_context: prev_name=sampling-10721 prev_pid=10724 prev_prio=99 prev_state=0x4c042 ==> next_name=ROOT/0 next_pid=0 next_prio=-1 sampling-10721 10724 [000] 7174.323117: cobalt_core:cobalt_timer_stop: timer=0xffff888470036828 swapper 0 [000] 7174.323117: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 kernel-drv-task11 2456 [003] 7174.323124: irq:irq_pipeline_entry: irq=33044 swapper 0 [000] 7174.323125: cobalt_core:cobalt_timer_start: timer=0xffff888470036298([host-timer/0]) value=1415302 interval=0 mode=0x0 1ms-polling-task 3148 [001] 7174.323125: irq:irq_pipeline_entry: irq=33044 swapper 0 [000] 7174.323126: cobalt_core:cobalt_timer_start: timer=0xffff888470036298([host-timer/0]) value=7336453 interval=0 mode=0x0 swapper 0 [000] 7174.323126: cobalt_core:cobalt_timer_start: timer=0xffff888470036298([host-timer/0]) value=1413993 interval=0 mode=0x0 1ms-polling-task 3148 [001] 7174.323127: cobalt_core:cobalt_synch_sleepon: synch=0xffffffffa0a54058 1ms-polling-task 3148 [001] 7174.323127: cobalt_core:cobalt_thread_suspend: pid=3148 mask=0x2 timeout=0 timeout_mode=0 wchan=0xffffffffa0a54058 1ms-polling-task 3148 [001] 7174.323127: cobalt_core:cobalt_schedule: status=0x10000000 1ms-polling-task 3148 [001] 7174.323128: cobalt_core:cobalt_trace_pid: pid=3148, prio=93 1ms-polling-task 3148 [001] 7174.323128: cobalt_core:cobalt_switch_context: prev_name=1ms-polling-task76 prev_pid=3148 prev_prio=93 prev_state=0x48042 ==> next_name=rt-task20076 next_pid=3150 next_prio=93 rt-task20 3150 [001] 7174.323129: cobalt_core:cobalt_trace_pid: pid=3150, prio=93 kernel-drv-task11 2456 [003] 7174.323130: cobalt_core:cobalt_synch_wakeup: synch=0xffffffffa0a54058 kernel-drv-task11 2462 [002] 7174.323130: irq:irq_pipeline_entry: irq=33044 kernel-drv-task11 2456 [003] 7174.323131: cobalt_core:cobalt_thread_resume: name=1ms-polling-task76 pid=3148 mask=0x2 kernel-drv-task11 2456 [003] 7174.323131: cobalt_core:cobalt_trace_pid: pid=3148, prio=93 kernel-drv-task11 2456 [003] 7174.323131: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 2456 [003] 7174.323132: cobalt_core:cobalt_trace_pid: pid=2456, prio=94 rt-task20 3150 [001] 7174.323133: irq:irq_pipeline_entry: irq=33025 MAIN-TASK 3128 [000] 7174.323133: cobalt_core:cobalt_timer_start: timer=0xffff888470036298([host-timer/0]) value=999886 interval=0 mode=0x0 rt-task20 3150 [001] 7174.323133: cobalt_core:cobalt_schedule_remote: status=0x10000000 rt-task20 3150 [001] 7174.323134: cobalt_core:cobalt_schedule: status=0x10000000 rt-task20 3150 [001] 7174.323135: cobalt_core:cobalt_trace_pid: pid=3150, prio=93 kernel-drv-task11 2462 [002] 7174.323136: cobalt_core:cobalt_synch_sleepon: synch=0xffffffffa0a839b8 kernel-drv-task11 2462 [002] 7174.323136: cobalt_core:cobalt_thread_suspend: pid=2462 mask=0x2 timeout=0 timeout_mode=0 wchan=0xffffffffa0a839b8 kernel-drv-task11 2462 [002] 7174.323137: cobalt_core:cobalt_schedule: status=0x10000000 kernel-drv-task11 2462 [002] 7174.323137: cobalt_core:cobalt_trace_pid: pid=2462, prio=98 kernel-drv-task11 2462 [002] 7174.323138: cobalt_core:cobalt_switch_context: prev_name=kernel-drv-task11 prev_pid=2462 prev_prio=98 prev_state=0x42 ==> next_name=rt-task5 next_pid=3172 next_prio=92 rt-task5 3172 [002] 7174.323138: cobalt_core:cobalt_trace_pid: pid=3172, prio=92 latency test result: RTD| -2.334| -0.852| 24.850| 96| 0| -2.585| 9636.115 RTD| -2.417| -0.840| 27.158| 96| 0| -2.585| 9636.115 RTD| -2.408| -0.850| 26.248| 96| 0| -2.585| 9636.115 RTD| -2.453| -0.769| 23.633| 96| 0| -2.585| 9636.115 RTD| -2.288| -0.778| 26.945| 96| 0| -2.585| 9636.115 RTD| -2.415| -0.811| 28.071| 96| 0| -2.585| 9636.115 RTD| -2.345| -0.863| 22.760| 96| 0| -2.585| 9636.115 RTD| -2.369| -0.810| 26.263| 96| 0| -2.585| 9636.115 RTD| -2.307| -0.874| 23.359| 96| 0| -2.585| 9636.115 RTD| -2.334| -0.890| 27.921| 96| 0| -2.585| 9636.115 RTD| -2.374| -0.757| 24.251| 96| 0| -2.585| 9636.115 RTD| -2.440| -0.786| 19.938| 96| 0| -2.585| 9636.115 RTD| -2.343| -0.823| 27.010| 96| 0| -2.585| 9636.115 RTD| -2.339| -0.902| 29.216| 96| 0| -2.585| 9636.115 RTD| -2.351| -0.826| 19.601| 96| 0| -2.585| 9636.115 RTT| 00:37:28 (periodic user-mode task, 100 us period, priority 99) RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat best|--lat worst RTD| -2.338| -0.859| 28.091| 96| 0| -2.585| 9636.115 RTD| -2.342| -0.905| 23.030| 96| 0| -2.585| 9636.115 RTD| -2.402| -0.778| 26.933| 96| 0| -2.585| 9636.115 RTD| -2.318| -0.726| 27.356| 96| 0| -2.585| 9636.115 RTD| -2.332| -0.820| 19.761| 96| 0| -2.585| 9636.115 RTD| -2.393| -0.868| 24.489| 96| 0| -2.585| 9636.115 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: schedule delay 15ms 2025-11-13 4:00 ` JerryJun @ 2025-11-13 5:31 ` Jan Kiszka 2025-11-14 2:48 ` JerryJun 0 siblings, 1 reply; 11+ messages in thread From: Jan Kiszka @ 2025-11-13 5:31 UTC (permalink / raw) To: JerryJun, xenomai@lists.linux.dev On 13.11.25 05:00, JerryJun wrote: > > We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 > swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not seeing that event in the trace. Furthermore, I always for get about that, it is useful to have irq_vectors events because those include timer irqs. But it is unlikely that we missed any in that gap because they tend to trigger activities like cobalt_core:cobalt_timer_expire. What is more likely here is that your hardware or firmware is not letting IRQs through. We could confirm that if the issue is reproducible while have function tracing enabled. That comes with high overhead, but the detailed result can tell us what the kernel did while there were no interrupts. There is also native tooling by the kernel to detect "hardware noise", see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its nature, this noise would affect Xenomai equally. Jan -- Siemens AG, Foundational Technologies Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re:Re: schedule delay 15ms 2025-11-13 5:31 ` Jan Kiszka @ 2025-11-14 2:48 ` JerryJun 2025-11-14 5:38 ` Jan Kiszka 0 siblings, 1 reply; 11+ messages in thread From: JerryJun @ 2025-11-14 2:48 UTC (permalink / raw) To: xenomai@lists.linux.dev, Jan Kiszka [-- Attachment #1: Type: text/plain, Size: 1929 bytes --] We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. include trace point events : irq_vectors:call_function_entry irq_vectors:call_function_exit irq_vectors:call_function_single_entry irq_vectors:call_function_single_exit 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >On 13.11.25 05:00, JerryJun wrote: >> >> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >> > > swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 > swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 > >So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >seeing that event in the trace. Furthermore, I always for get about >that, it is useful to have irq_vectors events because those include >timer irqs. But it is unlikely that we missed any in that gap because >they tend to trigger activities like cobalt_core:cobalt_timer_expire. > >What is more likely here is that your hardware or firmware is not >letting IRQs through. We could confirm that if the issue is reproducible >while have function tracing enabled. That comes with high overhead, but >the detailed result can tell us what the kernel did while there were no >interrupts. > >There is also native tooling by the kernel to detect "hardware noise", >see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >nature, this noise would affect Xenomai equally. > >Jan > >-- >Siemens AG, Foundational Technologies >Linux Expert Center [-- Attachment #2: delay2.txt --] [-- Type: text/plain, Size: 22596 bytes --] We added some trace information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. include trace point event : irq_vectors:call_function_entry irq_vectors:call_function_exit irq_vectors:call_function_single_entry irq_vectors:call_function_single_exit rt-task3 2737 [001] 6208.695888: cobalt_core:cobalt_trace_pid: pid=2737, prio=91 rt-task3 2737 [001] 6208.695888: cobalt_core:cobalt_synch_acquire: synch=0xffffc9000097a908 rt-task3 2737 [001] 6208.695890: cobalt_core:cobalt_synch_release: synch=0xffffc9000097a908 rt-task3 2737 [001] 6208.695890: cobalt_core:cobalt_synch_sleepon: synch=0xffffc9000097ab08 rt-task3 2737 [001] 6208.695890: cobalt_core:cobalt_thread_suspend: pid=2737 mask=0x2 timeout=6208672099128 timeout_mode=1 wchan=0xffffc9000097ab08 rt-task3 2737 [001] 6208.695890: cobalt_core:cobalt_timer_start: timer=0xffffc90000979cf0(MAIN-Thread) value=6208672099128 interval=0 mode=0x1 rt-task3 2737 [001] 6208.695891: cobalt_core:cobalt_schedule: status=0x10000000 rt-task3 2737 [001] 6208.695891: cobalt_core:cobalt_trace_pid: pid=2737, prio=91 rt-task3 2737 [001] 6208.695891: cobalt_core:cobalt_switch_context: prev_name=rt-task3 prev_pid=2737 prev_prio=91 prev_state=0x48046 ==> next_name=ROOT/1 next_pid=0 next_prio=-1 rt-task3 2737 [001] 6208.695892: cobalt_core:cobalt_timer_stop: timer=0xffff8884700b6828 MAIN-Thread 2798 [001] 6208.695892: cobalt_core:cobalt_trace_pid: pid=2798, prio=-1 swapper 0 [001] 6208.695901: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6298([host-timer/1]) value=94752 interval=0 mode=0x0 swapper 0 [001] 6208.695906: irq:irq_pipeline_entry: irq=33027 swapper 0 [001] 6208.695906: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [001] 6208.695907: cobalt_core:cobalt_timer_expire: timer=0xffffc90000978ef0 swapper 0 [001] 6208.695907: cobalt_core:cobalt_thread_resume: name=rt-task474 pid=2738 mask=0x4 swapper 0 [001] 6208.695907: cobalt_core:cobalt_trace_pid: pid=2738, prio=85 swapper 0 [001] 6208.695907: cobalt_core:cobalt_timer_stop: timer=0xffffc90000978ef0 swapper 0 [001] 6208.695908: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [001] 6208.695908: irq:irq_pipeline_exit: irq=33027 swapper 0 [001] 6208.695908: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 6208.695909: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 6208.695909: cobalt_core:cobalt_switch_context: prev_name=ROOT/1 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task474 next_pid=2738 next_prio=85 swapper 0 [001] 6208.695909: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task4 2738 [001] 6208.695910: cobalt_core:cobalt_trace_pid: pid=2738, prio=85 rt-task4 2738 [001] 6208.695911: cobalt_core:cobalt_thread_suspend: pid=2738 mask=0x4 timeout=6208672120609 timeout_mode=1 wchan=(nil) rt-task4 2738 [001] 6208.695911: cobalt_core:cobalt_timer_start: timer=0xffffc90000978ef0(MAIN-Thread) value=6208672120609 interval=0 mode=0x1 rt-task4 2738 [001] 6208.695911: cobalt_core:cobalt_schedule: status=0x10000000 rt-task4 2738 [001] 6208.695912: cobalt_core:cobalt_trace_pid: pid=2738, prio=85 rt-task4 2738 [001] 6208.695912: cobalt_core:cobalt_switch_context: prev_name=rt-task4 prev_pid=2738 prev_prio=85 prev_state=0x48044 ==> next_name=ROOT/1 next_pid=0 next_prio=-1 rt-task4 2738 [001] 6208.695912: cobalt_core:cobalt_timer_stop: timer=0xffff8884700b6828 swapper 0 [001] 6208.695913: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 6208.695920: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 6208.695920: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [002] 6208.695921: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096eef0 swapper 0 [002] 6208.695921: cobalt_core:cobalt_thread_resume: name=rt-task2 pid=2762 mask=0x4 swapper 0 [002] 6208.695921: cobalt_core:cobalt_trace_pid: pid=2762, prio=85 swapper 0 [002] 6208.695921: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096eef0 swapper 0 [002] 6208.695922: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [002] 6208.695922: irq:irq_pipeline_exit: irq=33027 swapper 0 [002] 6208.695922: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 6208.695923: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 6208.695923: cobalt_core:cobalt_switch_context: prev_name=ROOT/2 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task2 next_pid=2762 next_prio=85 swapper 0 [002] 6208.695923: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task2 2762 [002] 6208.695924: cobalt_core:cobalt_trace_pid: pid=2762, prio=85 rt-task2 2762 [002] 6208.695925: cobalt_core:cobalt_thread_suspend: pid=2762 mask=0x4 timeout=6208672084819 timeout_mode=1 wchan=(nil) rt-task2 2762 [002] 6208.695925: cobalt_core:cobalt_timer_start: timer=0xffffc9000096eef0(MAIN-Thread) value=6208672084819 interval=0 mode=0x1 swapper 0 [001] 6208.695925: irq:irq_pipeline_entry: irq=33027 rt-task2 2762 [002] 6208.695926: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 6208.695926: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt rt-task2 2762 [002] 6208.695926: cobalt_core:cobalt_trace_pid: pid=2762, prio=85 rt-task2 2762 [002] 6208.695926: cobalt_core:cobalt_switch_context: prev_name=rt-task2 prev_pid=2762 prev_prio=85 prev_state=0x48044 ==> next_name=ROOT/2 next_pid=0 next_prio=-1 rt-task2 2762 [002] 6208.695927: cobalt_core:cobalt_timer_stop: timer=0xffff888470136828 swapper 0 [002] 6208.695927: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 6208.695928: cobalt_core:cobalt_timer_expire: timer=0xffffc90000977ef0 swapper 0 [001] 6208.695928: cobalt_core:cobalt_thread_resume: name=rt-task1 pid=2739 mask=0x4 swapper 0 [001] 6208.695928: cobalt_core:cobalt_trace_pid: pid=2739, prio=86 swapper 0 [001] 6208.695928: cobalt_core:cobalt_timer_stop: timer=0xffffc90000977ef0 swapper 0 [001] 6208.695929: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [001] 6208.695929: irq:irq_pipeline_exit: irq=33027 swapper 0 [001] 6208.695929: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 6208.695930: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [001] 6208.695930: cobalt_core:cobalt_switch_context: prev_name=ROOT/1 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task1 next_pid=2739 next_prio=86 swapper 0 [001] 6208.695930: cobalt_core:cobalt_timer_start: timer=0xffff8884700b6828([watchdog]) value=1000000000 interval=0 mode=0x0 rt-task1 2739 [001] 6208.695931: cobalt_core:cobalt_trace_pid: pid=2739, prio=86 rt-task1 2739 [001] 6208.695933: cobalt_core:cobalt_thread_suspend: pid=2739 mask=0x4 timeout=6208672142529 timeout_mode=1 wchan=(nil) rt-task1 2739 [001] 6208.695933: cobalt_core:cobalt_timer_start: timer=0xffffc90000977ef0(MAIN-Thread) value=6208672142529 interval=0 mode=0x1 rt-task1 2739 [001] 6208.695933: cobalt_core:cobalt_schedule: status=0x10000000 rt-task1 2739 [001] 6208.695934: cobalt_core:cobalt_trace_pid: pid=2739, prio=86 rt-task1 2739 [001] 6208.695934: cobalt_core:cobalt_switch_context: prev_name=rt-task1 prev_pid=2739 prev_prio=86 prev_state=0x48044 ==> next_name=ROOT/1 next_pid=0 next_prio=-1 rt-task1 2739 [001] 6208.695935: cobalt_core:cobalt_timer_stop: timer=0xffff8884700b6828 swapper 0 [001] 6208.695935: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 6208.695937: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 6208.695937: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [002] 6208.695937: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096e0f0 swapper 0 [002] 6208.695938: cobalt_core:cobalt_thread_resume: name=rt-task5 pid=2764 mask=0x4 swapper 0 [002] 6208.695938: cobalt_core:cobalt_trace_pid: pid=2764, prio=92 swapper 0 [002] 6208.695938: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096e0f0 swapper 0 [002] 6208.695939: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [002] 6208.695939: irq:irq_pipeline_exit: irq=33027 swapper 0 [002] 6208.695939: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 6208.695940: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 6208.695940: cobalt_core:cobalt_switch_context: prev_name=ROOT/2 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task5 next_pid=2764 next_prio=92 swapper 0 [002] 6208.695940: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 swapper 0 [000] 6208.695941: irq:irq_pipeline_entry: irq=33027 rt-task5 2764 [002] 6208.695941: cobalt_core:cobalt_trace_pid: pid=2764, prio=92 swapper 0 [000] 6208.695941: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [000] 6208.695942: cobalt_core:cobalt_timer_expire: timer=0xffff888470036298 swapper 0 [000] 6208.695942: irq:irq_handler_exit: irq=33027 ret=handled rt-task5 2764 [002] 6208.695942: cobalt_core:cobalt_thread_suspend: pid=2764 mask=0x4 timeout=6208672301501 timeout_mode=1 wchan=(nil) swapper 0 [000] 6208.695942: irq:irq_pipeline_exit: irq=33027 rt-task5 2764 [002] 6208.695942: cobalt_core:cobalt_timer_start: timer=0xffffc9000096e0f0(MAIN-Thread) value=6208672301501 interval=0 mode=0x1 swapper 0 [000] 6208.695943: irq:irq_handler_entry: irq=27 name=proxy tick rt-task5 2764 [002] 6208.695943: cobalt_core:cobalt_schedule: status=0x10000000 rt-task5 2764 [002] 6208.695943: cobalt_core:cobalt_trace_pid: pid=2764, prio=92 rt-task5 2764 [002] 6208.695943: cobalt_core:cobalt_switch_context: prev_name=rt-task5 prev_pid=2764 prev_prio=92 prev_state=0x48044 ==> next_name=ROOT/2 next_pid=0 next_prio=-1 rt-task5 2764 [002] 6208.695944: cobalt_core:cobalt_timer_stop: timer=0xffff888470136828 swapper 0 [002] 6208.695944: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [000] 6208.695948: cobalt_core:cobalt_timer_start: timer=0xffff888470036298([host-timer/0]) value=107378 interval=0 mode=0x0 swapper 0 [000] 6208.695948: irq:irq_handler_exit: irq=27 ret=handled swapper 0 [000] 6208.708726: irq:irq_pipeline_entry: irq=33027 swapper 0 [001] 6208.708726: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 6208.708726: irq:irq_pipeline_entry: irq=33027 swapper 0 [000] 6208.708726: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [003] 6208.708727: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 6208.708727: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [000] 6208.708727: cobalt_core:cobalt_timer_expire: timer=0xffff888470036298 swapper 0 [001] 6208.708727: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [003] 6208.708727: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [000] 6208.708727: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [002] 6208.708727: cobalt_core:cobalt_timer_expire: timer=0xffffc900009744f0 swapper 0 [000] 6208.708728: irq:irq_pipeline_exit: irq=33027 swapper 0 [002] 6208.708728: cobalt_core:cobalt_thread_resume: name=rt-task8 pid=2750 mask=0x4 swapper 0 [002] 6208.708728: cobalt_core:cobalt_trace_pid: pid=2750, prio=85 swapper 0 [000] 6208.708728: irq:irq_handler_entry: irq=27 name=proxy tick swapper 0 [002] 6208.708728: cobalt_core:cobalt_timer_stop: timer=0xffffc900009744f0 swapper 0 [002] 6208.708729: cobalt_core:cobalt_timer_expire: timer=0xffffc900009736f0 swapper 0 [002] 6208.708729: cobalt_core:cobalt_thread_resume: name=rt-task7 pid=2753 mask=0x4 swapper 0 [002] 6208.708729: cobalt_core:cobalt_trace_pid: pid=2753, prio=85 swapper 0 [002] 6208.708729: cobalt_core:cobalt_timer_stop: timer=0xffffc900009736f0 swapper 0 [002] 6208.708730: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096eef0 swapper 0 [002] 6208.708730: cobalt_core:cobalt_thread_resume: name=rt-task2 pid=2762 mask=0x4 swapper 0 [002] 6208.708730: cobalt_core:cobalt_trace_pid: pid=2762, prio=85 swapper 0 [002] 6208.708730: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096eef0 swapper 0 [002] 6208.708731: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096fcf0 swapper 0 [002] 6208.708731: cobalt_core:cobalt_thread_resume: name=rt-task6 pid=2761 mask=0x4 swapper 0 [002] 6208.708731: cobalt_core:cobalt_trace_pid: pid=2761, prio=92 swapper 0 [002] 6208.708731: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096fcf0 swapper 0 [002] 6208.708732: cobalt_core:cobalt_timer_expire: timer=0xffffc9000096e0f0 swapper 0 [002] 6208.708732: cobalt_core:cobalt_thread_resume: name=rt-task5 pid=2764 mask=0x4 swapper 0 [002] 6208.708732: cobalt_core:cobalt_trace_pid: pid=2764, prio=92 swapper 0 [002] 6208.708733: cobalt_core:cobalt_timer_stop: timer=0xffffc9000096e0f0 swapper 0 [002] 6208.708733: cobalt_core:cobalt_timer_expire: timer=0xffff888470136298 swapper 0 [002] 6208.708733: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [001] 6208.708733: cobalt_core:cobalt_timer_expire: timer=0xffff8884700b6298 swapper 0 [002] 6208.708734: irq:irq_pipeline_exit: irq=33027 swapper 0 [001] 6208.708734: cobalt_core:cobalt_timer_expire: timer=0xffffc90000979cf0 swapper 0 [002] 6208.708734: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [001] 6208.708734: cobalt_core:cobalt_thread_resume: name=rt-task3 pid=2737 mask=0x4 swapper 0 [001] 6208.708735: cobalt_core:cobalt_trace_pid: pid=2737, prio=91 swapper 0 [001] 6208.708735: cobalt_core:cobalt_timer_stop: timer=0xffffc90000979cf0 swapper 0 [001] 6208.708735: cobalt_core:cobalt_synch_forget: synch=0xffffc9000097ab08 swapper 0 [001] 6208.708735: cobalt_core:cobalt_timer_expire: timer=0xffffc90000978ef0 swapper 0 [001] 6208.708736: cobalt_core:cobalt_thread_resume: name=rt-task474 pid=2738 mask=0x4 swapper 0 [001] 6208.708736: cobalt_core:cobalt_trace_pid: pid=2738, prio=85 swapper 0 [001] 6208.708736: cobalt_core:cobalt_timer_stop: timer=0xffffc90000978ef0 swapper 0 [001] 6208.708737: cobalt_core:cobalt_timer_expire: timer=0xffffc90000977ef0 swapper 0 [001] 6208.708737: cobalt_core:cobalt_thread_resume: name=rt-task1 pid=2739 mask=0x4 swapper 0 [001] 6208.708737: cobalt_core:cobalt_trace_pid: pid=2739, prio=86 swapper 0 [001] 6208.708737: cobalt_core:cobalt_timer_stop: timer=0xffffc90000977ef0 swapper 0 [001] 6208.708738: cobalt_core:cobalt_timer_expire: timer=0xffffffffa0a556b8 swapper 0 [001] 6208.708738: cobalt_core:cobalt_thread_resume: name=kernel-drv-task10 pid=2456 mask=0x4 swapper 0 [001] 6208.708738: cobalt_core:cobalt_trace_pid: pid=2456, prio=94 swapper 0 [001] 6208.708738: cobalt_core:cobalt_timer_stop: timer=0xffffffffa0a556b8 swapper 0 [001] 6208.708739: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0a559e8 swapper 0 [001] 6208.708739: cobalt_core:cobalt_timer_expire: timer=0xffffc900009770f0 swapper 0 [001] 6208.708739: cobalt_core:cobalt_thread_resume: name=1ms-polling-task pid=2740 mask=0x4 swapper 0 [001] 6208.708740: cobalt_core:cobalt_trace_pid: pid=2740, prio=93 swapper 0 [001] 6208.708740: cobalt_core:cobalt_timer_stop: timer=0xffffc900009770f0 swapper 0 [001] 6208.708740: cobalt_core:cobalt_timer_expire: timer=0xffffc900009752f0 swapper 0 [001] 6208.708740: cobalt_core:cobalt_thread_resume: name=rt-task20 pid=2742 mask=0x4 swapper 0 [001] 6208.708741: cobalt_core:cobalt_trace_pid: pid=2742, prio=93 swapper 0 [001] 6208.708741: cobalt_core:cobalt_timer_stop: timer=0xffffc900009752f0 swapper 0 [001] 6208.708741: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0a86d80 swapper 0 [001] 6208.708741: cobalt_core:cobalt_timer_expire: timer=0xffffffffa0a86fe0 swapper 0 [001] 6208.708742: cobalt_core:cobalt_thread_resume: name=kernel-drv-rttask11 pid=2462 mask=0x4 swapper 0 [001] 6208.708742: cobalt_core:cobalt_trace_pid: pid=2462, prio=98 swapper 0 [001] 6208.708742: cobalt_core:cobalt_timer_stop: timer=0xffffffffa0a86fe0 swapper 0 [001] 6208.708742: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0a87310 swapper 0 [001] 6208.708743: cobalt_core:cobalt_timer_expire: timer=0xffffc900009760f0 swapper 0 [001] 6208.708743: cobalt_core:cobalt_thread_resume: name=rt-task19 pid=2741 mask=0x4 swapper 0 [001] 6208.708743: cobalt_core:cobalt_trace_pid: pid=2741, prio=93 swapper 0 [001] 6208.708744: cobalt_core:cobalt_timer_stop: timer=0xffffc900009760f0 swapper 0 [001] 6208.708744: cobalt_core:cobalt_synch_forget: synch=0xffffffffa0aabe00 swapper 0 [001] 6208.708744: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [003] 6208.708744: cobalt_core:cobalt_timer_expire: timer=0xffff8884701b6298 swapper 0 [001] 6208.708745: irq:irq_pipeline_exit: irq=33027 swapper 0 [003] 6208.708745: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [001] 6208.708745: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 6208.708745: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [003] 6208.708745: irq:irq_pipeline_exit: irq=33027 swapper 0 [002] 6208.708746: cobalt_core:cobalt_switch_context: prev_name=ROOT/2 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=rt-task6 next_pid=2761 next_prio=92 swapper 0 [002] 6208.708746: cobalt_core:cobalt_timer_start: timer=0xffff888470136828([watchdog]) value=1000000000 interval=0 mode=0x0 swapper 0 [003] 6208.708746: irq:irq_handler_entry: irq=27 name=proxy tick ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: schedule delay 15ms 2025-11-14 2:48 ` JerryJun @ 2025-11-14 5:38 ` Jan Kiszka 2025-11-18 15:31 ` JerryJun 0 siblings, 1 reply; 11+ messages in thread From: Jan Kiszka @ 2025-11-14 5:38 UTC (permalink / raw) To: JerryJun, xenomai@lists.linux.dev On 14.11.25 03:48, JerryJun wrote: > > We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. > include trace point events : > irq_vectors:call_function_entry > irq_vectors:call_function_exit > irq_vectors:call_function_single_entry > irq_vectors:call_function_single_exit > If there are no interrupt in that phase while, e.g., some timer interrupt should have occurred, then you should definitely check for hardware/firmware related delays that the OS cannot influence. Or for power-saving / thermal-throttling causes. Jan > 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >> On 13.11.25 05:00, JerryJun wrote: >>> >>> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >>> >> >> swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 >> swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 >> >> So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >> seeing that event in the trace. Furthermore, I always for get about >> that, it is useful to have irq_vectors events because those include >> timer irqs. But it is unlikely that we missed any in that gap because >> they tend to trigger activities like cobalt_core:cobalt_timer_expire. >> >> What is more likely here is that your hardware or firmware is not >> letting IRQs through. We could confirm that if the issue is reproducible >> while have function tracing enabled. That comes with high overhead, but >> the detailed result can tell us what the kernel did while there were no >> interrupts. >> >> There is also native tooling by the kernel to detect "hardware noise", >> see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >> nature, this noise would affect Xenomai equally. >> >> Jan >> >> -- >> Siemens AG, Foundational Technologies >> Linux Expert Center -- Siemens AG, Foundational Technologies Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re:Re: schedule delay 15ms 2025-11-14 5:38 ` Jan Kiszka @ 2025-11-18 15:31 ` JerryJun 2025-11-18 16:00 ` Jan Kiszka 0 siblings, 1 reply; 11+ messages in thread From: JerryJun @ 2025-11-18 15:31 UTC (permalink / raw) To: Jan Kiszka, xenomai@lists.linux.dev Strangely enough, this delay wasn't present on the 4.19.89-ipip kernel - it only emerged after upgrading to 5.10.199-dovetail, despite no changes being made to the power management policy or thermal throttling settings during the update. Could this be related to potential instability in the HPET or TSC clock sources? And does upgrading to a new kernel version also necessitate a BIOS update? At 2025-11-14 13:38:36, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >On 14.11.25 03:48, JerryJun wrote: >> >> We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. >> include trace point events : >> irq_vectors:call_function_entry >> irq_vectors:call_function_exit >> irq_vectors:call_function_single_entry >> irq_vectors:call_function_single_exit >> > >If there are no interrupt in that phase while, e.g., some timer >interrupt should have occurred, then you should definitely check for >hardware/firmware related delays that the OS cannot influence. Or for >power-saving / thermal-throttling causes. > >Jan > >> 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >>> On 13.11.25 05:00, JerryJun wrote: >>>> >>>> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >>>> >>> >>> swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 >>> swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 >>> >>> So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >>> seeing that event in the trace. Furthermore, I always for get about >>> that, it is useful to have irq_vectors events because those include >>> timer irqs. But it is unlikely that we missed any in that gap because >>> they tend to trigger activities like cobalt_core:cobalt_timer_expire. >>> >>> What is more likely here is that your hardware or firmware is not >>> letting IRQs through. We could confirm that if the issue is reproducible >>> while have function tracing enabled. That comes with high overhead, but >>> the detailed result can tell us what the kernel did while there were no >>> interrupts. >>> >>> There is also native tooling by the kernel to detect "hardware noise", >>> see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >>> nature, this noise would affect Xenomai equally. >>> >>> Jan >>> >>> -- >>> Siemens AG, Foundational Technologies >>> Linux Expert Center > > >-- >Siemens AG, Foundational Technologies >Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: schedule delay 15ms 2025-11-18 15:31 ` JerryJun @ 2025-11-18 16:00 ` Jan Kiszka 2025-11-20 8:10 ` JerryJun 0 siblings, 1 reply; 11+ messages in thread From: Jan Kiszka @ 2025-11-18 16:00 UTC (permalink / raw) To: JerryJun, xenomai@lists.linux.dev On 18.11.25 16:31, JerryJun wrote: > > Strangely enough, this delay wasn't present on the 4.19.89-ipip kernel - it only emerged after upgrading to 5.10.199-dovetail, despite no changes being made to the power management policy or thermal throttling settings during the update. Could this be related to potential instability in the HPET or TSC clock sources? And does upgrading to a new kernel version also necessitate a BIOS update? > Generally spoken, a newer kernel could always have changed something regarding how power tuning is done. Simple scenario: a kernel config switch was renaming or gained a new dependency that is not fulfill -> tuning feature is silently lost. Another reason for different behavior could be the enabling (maybe even by default) of a new feature that has unexpected side effects. You may check if there are new drivers active, new devices available. Jan > At 2025-11-14 13:38:36, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >> On 14.11.25 03:48, JerryJun wrote: >>> >>> We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. >>> include trace point events : >>> irq_vectors:call_function_entry >>> irq_vectors:call_function_exit >>> irq_vectors:call_function_single_entry >>> irq_vectors:call_function_single_exit >>> >> >> If there are no interrupt in that phase while, e.g., some timer >> interrupt should have occurred, then you should definitely check for >> hardware/firmware related delays that the OS cannot influence. Or for >> power-saving / thermal-throttling causes. >> >> Jan >> >>> 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >>>> On 13.11.25 05:00, JerryJun wrote: >>>>> >>>>> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >>>>> >>>> >>>> swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 >>>> swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 >>>> >>>> So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >>>> seeing that event in the trace. Furthermore, I always for get about >>>> that, it is useful to have irq_vectors events because those include >>>> timer irqs. But it is unlikely that we missed any in that gap because >>>> they tend to trigger activities like cobalt_core:cobalt_timer_expire. >>>> >>>> What is more likely here is that your hardware or firmware is not >>>> letting IRQs through. We could confirm that if the issue is reproducible >>>> while have function tracing enabled. That comes with high overhead, but >>>> the detailed result can tell us what the kernel did while there were no >>>> interrupts. >>>> >>>> There is also native tooling by the kernel to detect "hardware noise", >>>> see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >>>> nature, this noise would affect Xenomai equally. >>>> >>>> Jan >>>> >>>> -- >>>> Siemens AG, Foundational Technologies >>>> Linux Expert Center >> >> >> -- >> Siemens AG, Foundational Technologies >> Linux Expert Center -- Siemens AG, Foundational Technologies Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re:Re: schedule delay 15ms 2025-11-18 16:00 ` Jan Kiszka @ 2025-11-20 8:10 ` JerryJun 2025-11-20 18:53 ` Jan Kiszka 0 siblings, 1 reply; 11+ messages in thread From: JerryJun @ 2025-11-20 8:10 UTC (permalink / raw) To: Jan Kiszka, xenomai@lists.linux.dev [-- Attachment #1: Type: text/plain, Size: 3940 bytes --] Which configurations do you think could cause this delay? During this process, the hardware remained unchanged. We used the following configurations and attempted to disable certain features in the kernel boot parameters, but it didn't work: xenomai.smi=disabled intel_idle.max_cstate=0 intel_pstate=disable nox2apic At 2025-11-19 00:00:12, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >On 18.11.25 16:31, JerryJun wrote: >> >> Strangely enough, this delay wasn't present on the 4.19.89-ipip kernel - it only emerged after upgrading to 5.10.199-dovetail, despite no changes being made to the power management policy or thermal throttling settings during the update. Could this be related to potential instability in the HPET or TSC clock sources? And does upgrading to a new kernel version also necessitate a BIOS update? >> > >Generally spoken, a newer kernel could always have changed something >regarding how power tuning is done. Simple scenario: a kernel config >switch was renaming or gained a new dependency that is not fulfill -> >tuning feature is silently lost. > >Another reason for different behavior could be the enabling (maybe even >by default) of a new feature that has unexpected side effects. You may >check if there are new drivers active, new devices available. > >Jan > >> At 2025-11-14 13:38:36, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >>> On 14.11.25 03:48, JerryJun wrote: >>>> >>>> We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. >>>> include trace point events : >>>> irq_vectors:call_function_entry >>>> irq_vectors:call_function_exit >>>> irq_vectors:call_function_single_entry >>>> irq_vectors:call_function_single_exit >>>> >>> >>> If there are no interrupt in that phase while, e.g., some timer >>> interrupt should have occurred, then you should definitely check for >>> hardware/firmware related delays that the OS cannot influence. Or for >>> power-saving / thermal-throttling causes. >>> >>> Jan >>> >>>> 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >>>>> On 13.11.25 05:00, JerryJun wrote: >>>>>> >>>>>> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >>>>>> >>>>> >>>>> swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 >>>>> swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 >>>>> >>>>> So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >>>>> seeing that event in the trace. Furthermore, I always for get about >>>>> that, it is useful to have irq_vectors events because those include >>>>> timer irqs. But it is unlikely that we missed any in that gap because >>>>> they tend to trigger activities like cobalt_core:cobalt_timer_expire. >>>>> >>>>> What is more likely here is that your hardware or firmware is not >>>>> letting IRQs through. We could confirm that if the issue is reproducible >>>>> while have function tracing enabled. That comes with high overhead, but >>>>> the detailed result can tell us what the kernel did while there were no >>>>> interrupts. >>>>> >>>>> There is also native tooling by the kernel to detect "hardware noise", >>>>> see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >>>>> nature, this noise would affect Xenomai equally. >>>>> >>>>> Jan >>>>> >>>>> -- >>>>> Siemens AG, Foundational Technologies >>>>> Linux Expert Center >>> >>> >>> -- >>> Siemens AG, Foundational Technologies >>> Linux Expert Center > >-- >Siemens AG, Foundational Technologies >Linux Expert Center [-- Attachment #2: 5.10.199-dovetail.txt --] [-- Type: text/plain, Size: 8154 bytes --] CONFIG_ACPI_ADXL=y CONFIG_APPLE_PROPERTIES=y CONFIG_AQTION=m CONFIG_ARCH_CLOCKSOURCE_INIT=y CONFIG_ARCH_CPUIDLE_HALTPOLL=y CONFIG_ARCH_HAS_COPY_MC=y CONFIG_ARCH_HAS_CPU_FINALIZE_INIT=y CONFIG_ARCH_HAS_DEBUG_VM_PGTABLE=y CONFIG_ARCH_HAS_DEBUG_WX=y CONFIG_ARCH_HAS_GIGANTIC_PAGE=y CONFIG_ARCH_HAS_NON_OVERLAPPING_ADDRESS_SPACE=y CONFIG_ARCH_HAS_PTE_DEVMAP=y CONFIG_ARCH_HAS_SET_DIRECT_MAP=y CONFIG_ARCH_STACKWALK=y CONFIG_ARCH_USE_MEMREMAP_PROT=y CONFIG_ARCH_USE_SYM_ANNOTATIONS=y CONFIG_ARCH_WANT_DEFAULT_BPF_JIT=y CONFIG_ARCH_WANT_IRQS_OFF_ACTIVATE_MM=y CONFIG_ARCH_WANT_LD_ORPHAN_WARN=y CONFIG_AS_AVX512=y CONFIG_AS_IS_GNU=y CONFIG_ASM_MODVERSIONS=y CONFIG_AS_SHA1_NI=y CONFIG_AS_SHA256_NI=y CONFIG_AS_TPAUSE=y CONFIG_AS_VERSION=23502 CONFIG_ATA_FORCE=y CONFIG_BLK_CGROUP_RWSTAT=y CONFIG_BLK_DEV_INTEGRITY_T10=m CONFIG_BLK_PM=y CONFIG_BPF_JIT_DEFAULT_ON=y CONFIG_BPF_UNPRIV_DEFAULT_OFF=y CONFIG_BUILDTIME_TABLE_SORT=y CONFIG_CC_CAN_LINK_STATIC=y CONFIG_CC_CAN_LINK=y CONFIG_CC_HAS_ASM_INLINE=y CONFIG_CC_HAS_INT128=y CONFIG_CC_HAS_KASAN_GENERIC=y CONFIG_CC_HAS_RETURN_THUNK=y CONFIG_CC_HAS_WORKING_NOSANITIZE_ADDRESS=y CONFIG_CC_VERSION_TEXT="gcc (Debian 10.2.1-6) 10.2.1 20210110" CONFIG_CGROUP_BPF=y CONFIG_CHELSIO_INLINE_CRYPTO=y CONFIG_COMEDI_NI_ROUTING=m CONFIG_CPU_IBPB_ENTRY=y CONFIG_CPU_IBRS_ENTRY=y CONFIG_CPU_SUP_HYGON=y CONFIG_CPU_SUP_ZHAOXIN=y CONFIG_CRYPTO_ARCH_HAVE_LIB_CHACHA=m CONFIG_CRYPTO_ARCH_HAVE_LIB_POLY1305=m CONFIG_CRYPTO_BLAKE2B=m CONFIG_CRYPTO_ECC=m CONFIG_CRYPTO_ESSIV=m CONFIG_CRYPTO_LIB_AES=y CONFIG_CRYPTO_LIB_ARC4=m CONFIG_CRYPTO_LIB_BLAKE2S_GENERIC=y CONFIG_CRYPTO_LIB_CHACHA_GENERIC=m CONFIG_CRYPTO_LIB_DES=m CONFIG_CRYPTO_LIB_POLY1305_GENERIC=m CONFIG_CRYPTO_LIB_POLY1305_RSIZE=11 CONFIG_CRYPTO_LIB_SHA256=y CONFIG_CRYPTO_SKCIPHER2=y CONFIG_CRYPTO_SKCIPHER=m CONFIG_CRYPTO_USER_API_ENABLE_OBSOLETE=y CONFIG_CRYPTO_XXHASH=m CONFIG_CRYPTO_ZSTD=m CONFIG_DEBUG_FS_ALLOW_ALL=y CONFIG_DEBUG_MISC=y CONFIG_DECOMPRESS_ZSTD=y CONFIG_DEFAULT_INIT="" CONFIG_DIMLIB=y CONFIG_DMA_OPS=y CONFIG_DOVETAIL_LEGACY_SYSCALL_RANGE=y CONFIG_DOVETAIL=y CONFIG_DRM_AMD_DC_DCN=y CONFIG_DRM_GEM_SHMEM_HELPER=y CONFIG_DRM_I915_FENCE_TIMEOUT=10000 CONFIG_DRM_I915_FORCE_PROBE="" CONFIG_DRM_I915_HEARTBEAT_INTERVAL=2500 CONFIG_DRM_I915_MAX_REQUEST_BUSYWAIT=8000 CONFIG_DRM_I915_PREEMPT_TIMEOUT=640 CONFIG_DRM_I915_STOP_TIMEOUT=100 CONFIG_DRM_I915_TIMESLICE_DURATION=1 CONFIG_DRM_I915_USERFAULT_AUTOSUSPEND=250 CONFIG_DRM_TTM_DMA_PAGE_POOL=y CONFIG_DRM_TTM_HELPER=m CONFIG_DRM_VRAM_HELPER=m CONFIG_DYNAMIC_EVENTS=y CONFIG_EFI_CUSTOM_SSDT_OVERLAYS=y CONFIG_EFI_DEV_PATH_PARSER=y CONFIG_EFI_EARLYCON=y CONFIG_EFI_GENERIC_STUB_INITRD_CMDLINE_LOADER=y CONFIG_EFI_STUB=y CONFIG_ETHTOOL_NETLINK=y CONFIG_FB_BACKLIGHT=m CONFIG_FW_CACHE=y CONFIG_FW_LOADER_PAGED_BUF=y CONFIG_GCC_VERSION=100201 CONFIG_GENERIC_ENTRY=y CONFIG_GENERIC_GETTIMEOFDAY=y CONFIG_GENERIC_PTDUMP=y CONFIG_GENERIC_VDSO_TIME_NS=y CONFIG_GPIO_CDEV_V1=y CONFIG_GPIO_CDEV=y CONFIG_HARDIRQS_SW_RESEND=y CONFIG_HAVE_ARCH_JUMP_LABEL_RELATIVE=y CONFIG_HAVE_ARCH_JUMP_LABEL=y CONFIG_HAVE_ARCH_KASAN_VMALLOC=y CONFIG_HAVE_ARCH_KCSAN=y CONFIG_HAVE_ARCH_SECCOMP=y CONFIG_HAVE_ARCH_STACKLEAK=y CONFIG_HAVE_ARCH_USERFAULTFD_WP=y CONFIG_HAVE_ASM_MODVERSIONS=y CONFIG_HAVE_CONTEXT_TRACKING=y CONFIG_HAVE_DOVETAIL=y CONFIG_HAVE_DYNAMIC_FTRACE_WITH_DIRECT_CALLS=y CONFIG_HAVE_EISA=y CONFIG_HAVE_FAST_GUP=y CONFIG_HAVE_FUNCTION_ARG_ACCESS_API=y CONFIG_HAVE_GENERIC_VDSO=y CONFIG_HAVE_IRQ_PIPELINE=y CONFIG_HAVE_KERNEL_ZSTD=y CONFIG_HAVE_KVM_NO_POLL=y CONFIG_HAVE_MOVE_PMD=y CONFIG_HAVE_PCI=y CONFIG_HAVE_PERCPU_PREEMPT_COUNT=y CONFIG_HAVE_POSIX_CPU_TIMERS_TASK_WORK=y CONFIG_HAVE_STACK_VALIDATION=y CONFIG_HAVE_STATIC_CALL_INLINE=y CONFIG_HAVE_STATIC_CALL=y CONFIG_HIBERNATION_SNAPSHOT_DEV=y CONFIG_HMM_MIRROR=y CONFIG_HYPERVISOR_GUEST=y CONFIG_IA32_FEAT_CTL=y CONFIG_IAVF=m CONFIG_IMA_MEASURE_ASYMMETRIC_KEYS=y CONFIG_IMA_QUEUE_EARLY_BOOT_KEYS=y CONFIG_INET_TABLE_PERTURB_ORDER=16 CONFIG_INFINIBAND_VIRT_DMA=y CONFIG_INIT_STACK_NONE=y CONFIG_INTEL_RAPL_CORE=m CONFIG_IOASID=y CONFIG_IOMMU_DMA=y CONFIG_IO_URING=y CONFIG_IO_WQ=y CONFIG_IP6_NF_MATCH_SRH=m CONFIG_IPMI_PLAT_DATA=y CONFIG_IPVLAN_L3S=y CONFIG_IRQ_MSI_IOMMU=y CONFIG_IRQ_PIPELINE=y CONFIG_ISDN_CAPI=y CONFIG_JOYSTICK_IFORCE_232=m CONFIG_JOYSTICK_IFORCE_USB=m CONFIG_KCMP=y CONFIG_KVM_GUEST=y CONFIG_KVM_WERROR=y CONFIG_KVM_XFER_TO_GUEST_WORK=y CONFIG_LD_ORPHAN_WARN=y CONFIG_LD_VERSION=235020000 CONFIG_LEDS_TRIGGER_AUDIO=m CONFIG_LIB_MEMNEQ=y CONFIG_LLD_VERSION=0 CONFIG_LOCALVERSION="-dovetail-xenomai-3.2.4-20240228" CONFIG_LSM="lockdown,yama,loadpin,safesetid,integrity,bpf" CONFIG_MAGIC_SYSRQ_SERIAL_SEQUENCE="" CONFIG_MAPPING_DIRTY_HELPERS=y CONFIG_MDIO_DEVRES=m CONFIG_MEDIA_CONTROLLER_DVB=y CONFIG_MEDIA_CONTROLLER_REQUEST_API=y CONFIG_MEDIA_PLATFORM_SUPPORT=y CONFIG_MEDIA_TEST_SUPPORT=y CONFIG_MEMREGION=y CONFIG_MMC_SDHCI_IO_ACCESSORS=y CONFIG_MMU_GATHER_RCU_TABLE_FREE=y CONFIG_MMU_GATHER_TABLE_FREE=y CONFIG_MXM_WMI=m CONFIG_NET_DEVLINK=y CONFIG_NETFILTER_XT_TARGET_MASQUERADE=m CONFIG_NET_REDIRECT=y CONFIG_NET_VENDOR_GOOGLE=y CONFIG_NET_VENDOR_PENSANDO=y CONFIG_NET_VENDOR_XILINX=y CONFIG_NF_CONNTRACK_BRIDGE=m CONFIG_NF_CT_PROTO_GRE=y CONFIG_NF_DUP_NETDEV=m CONFIG_NF_FLOW_TABLE_INET=m CONFIG_NF_FLOW_TABLE_IPV4=m CONFIG_NF_FLOW_TABLE_IPV6=m CONFIG_NF_FLOW_TABLE=m CONFIG_NF_LOG_NETDEV=m CONFIG_NF_NAT_MASQUERADE=y CONFIG_NFS_DISABLE_UDP_SUPPORT=y CONFIG_NF_TABLES_ARP=y CONFIG_NF_TABLES_BRIDGE=m CONFIG_NF_TABLES_INET=y CONFIG_NF_TABLES_IPV4=y CONFIG_NF_TABLES_IPV6=y CONFIG_NF_TABLES_NETDEV=y CONFIG_NFT_CONNLIMIT=m CONFIG_NFT_DUP_IPV4=m CONFIG_NFT_DUP_IPV6=m CONFIG_NFT_DUP_NETDEV=m CONFIG_NFT_FIB_IPV4=m CONFIG_NFT_FIB_IPV6=m CONFIG_NFT_FIB=m CONFIG_NFT_FWD_NETDEV=m CONFIG_NFT_OBJREF=m CONFIG_NFT_OSF=m CONFIG_NFT_REJECT_INET=m CONFIG_NFT_REJECT_IPV4=m CONFIG_NFT_REJECT_IPV6=m CONFIG_NFT_SOCKET=m CONFIG_NFT_SYNPROXY=m CONFIG_NFT_TPROXY=m CONFIG_NFT_TUNNEL=m CONFIG_NFT_XFRM=m CONFIG_NVDIMM_KEYS=y CONFIG_NVMEM_SYSFS=y CONFIG_PAGE_REPORTING=y CONFIG_PARAVIRT_CLOCK=y CONFIG_PARAVIRT=y CONFIG_PATA_TIMINGS=y CONFIG_PCIE_BUS_DEFAULT=y CONFIG_POSIX_CPU_TIMERS_TASK_WORK=y CONFIG_POWER_SUPPLY_HWMON=y CONFIG_PREEMPTION=y CONFIG_PROC_PID_ARCH_STATUS=y CONFIG_PROC_THERMAL_MMIO_RAPL=y CONFIG_PTP_1588_CLOCK_KVM=y CONFIG_RAID6_PQ_BENCHMARK=y CONFIG_RANDOM_TRUST_BOOTLOADER=y CONFIG_RD_ZSTD=y CONFIG_REGMAP_I2C=m CONFIG_REGMAP_SPI=m CONFIG_SATA_HOST=y CONFIG_SECURITY_SELINUX_SID2STR_CACHE_SIZE=256 CONFIG_SECURITY_SELINUX_SIDTAB_HASH_BITS=9 CONFIG_SERIAL_8250_DWLIB=y CONFIG_SERIAL_MCTRL_GPIO=y CONFIG_SHUFFLE_PAGE_ALLOCATOR=y CONFIG_SKB_EXTENSIONS=y CONFIG_SND_HDA_GENERIC_LEDS=y CONFIG_SND_INTEL_DSP_CONFIG=m CONFIG_SND_INTEL_NHLT=y CONFIG_SND_SOC_INTEL_APL=m CONFIG_SND_SOC_INTEL_CFL=m CONFIG_SND_SOC_INTEL_CNL=m CONFIG_SND_SOC_INTEL_GLK=m CONFIG_SND_SOC_INTEL_KBL=m CONFIG_SND_SOC_INTEL_SKL=m CONFIG_SND_SOC_INTEL_SKYLAKE_COMMON=m CONFIG_SND_SOC_INTEL_SKYLAKE_FAMILY=m CONFIG_SND_USB_AUDIO_USE_MEDIA_CONTROLLER=y CONFIG_SPECULATION_MITIGATIONS=y CONFIG_SPI_DYNAMIC=y CONFIG_SYMBOLIC_ERRNAME=y CONFIG_TASKS_RCU_GENERIC=y CONFIG_TASKS_TRACE_RCU=y CONFIG_TIME_NS=y CONFIG_TIPC_CRYPTO=y CONFIG_TRACE_IRQFLAGS_NMI_SUPPORT=y CONFIG_TREE_RCU=y CONFIG_TTY_PRINTK_LEVEL=6 CONFIG_UBIFS_FS_ZSTD=y CONFIG_UNIX_SCM=y CONFIG_USB_AUTOSUSPEND_DELAY=2 CONFIG_USB_COMMON=m CONFIG_VHOST_IOTLB=m CONFIG_VHOST_MENU=y CONFIG_VIDEO_V4L2_I2C=y CONFIG_VIRTIO_DMA_SHARED_BUFFER=m CONFIG_VMAP_PFN=y CONFIG_VSOCKETS_LOOPBACK=m CONFIG_WATCHDOG_OPEN_TIMEOUT=0 CONFIG_WLAN_VENDOR_MICROCHIP=y CONFIG_X86_HV_CALLBACK_VECTOR=y CONFIG_X86_INTERNODE_CACHE_SHIFT=12 CONFIG_X86_IOPL_IOPERM=y CONFIG_X86_UMIP=y CONFIG_X86_VMX_FEATURE_NAMES=y CONFIG_X86_VSMP=y CONFIG_X86_X2APIC=y CONFIG_XENO_REVISION_LEVEL=4 CONFIG_XENO_VERSION_MINOR=2 CONFIG_XENO_VERSION_STRING="3.2.4" CONFIG_XFRM_AH=m CONFIG_XFRM_ESP=m CONFIG_XFS_SUPPORT_V4=y CONFIG_XXHASH=y CONFIG_ZSTD_DECOMPRESS=y [-- Attachment #3: 4.19.89-ipipe.txt --] [-- Type: text/plain, Size: 5464 bytes --] CONFIG_ACPI_PROCESSOR_CSTATE=y CONFIG_ANON_INODES=y CONFIG_ARCH_CLOCKSOURCE_DATA=y CONFIG_ARCH_DEFCONFIG="arch/x86/configs/x86_64_defconfig" CONFIG_ARCH_DISCARD_MEMBLOCK=y CONFIG_ARCH_ENABLE_HUGEPAGE_MIGRATION=y CONFIG_ARCH_HAS_REFCOUNT=y CONFIG_ARCH_HAS_SG_CHAIN=y CONFIG_ARCH_HAS_UACCESS_MCSAFE=y CONFIG_ARCH_HAS_ZONE_DEVICE=y CONFIG_ARCH_SUPPORTS_OPTIMIZED_INLINING=y CONFIG_ARM_GIC_MAX_NR=1 CONFIG_AT803X_PHY=m CONFIG_AUDIT_TREE=y CONFIG_AUDIT_WATCH=y CONFIG_BACKLIGHT_LCD_SUPPORT=y CONFIG_BALLOON_COMPACTION=y CONFIG_BCH=m CONFIG_BLK_DEV_DAC960=m CONFIG_BLK_DEV_SR_VENDOR=y CONFIG_BLK_DEV_SX8=m CONFIG_BT_HCIUART_MRVL=y CONFIG_BUILDTIME_EXTABLE_SORT=y CONFIG_CALGARY_IOMMU_ENABLED_BY_DEFAULT=y CONFIG_CALGARY_IOMMU=y CONFIG_CAPI_AVM=y CONFIG_CAPI_EICON=y CONFIG_CC_HAS_STACKPROTECTOR_NONE=y CONFIG_CHASH=m CONFIG_CHR_DEV_OSST=m CONFIG_CIFS_ACL=y CONFIG_COMPACTION=y CONFIG_CRYPTO_AES_X86_64=m CONFIG_CRYPTO_BLKCIPHER2=y CONFIG_CRYPTO_BLKCIPHER=m CONFIG_CRYPTO_WORKQUEUE=y CONFIG_DECNET=m CONFIG_DECNET_NF_GRABULATOR=m CONFIG_DEFAULT_CFQ=y CONFIG_DEFAULT_IO_DELAY_TYPE=0 CONFIG_DEFAULT_IOSCHED="cfq" CONFIG_DEFAULT_SECURITY="" CONFIG_DMA_DIRECT_OPS=y CONFIG_DMA_VIRT_OPS=y CONFIG_DOUBLEFAULT=y CONFIG_DRM_AMD_DC_DCN1_0=y CONFIG_DSCC4=m CONFIG_DSCC4_PCI_RST=y CONFIG_DSCC4_PCISYNC=y CONFIG_EXOFS_FS=m CONFIG_EXT4_ENCRYPTION=y CONFIG_EXT4_FS_ENCRYPTION=y CONFIG_F2FS_FS_ENCRYPTION=y CONFIG_FB_BACKLIGHT=y CONFIG_FS_ENCRYPTION=m CONFIG_GCC_VERSION=80300 CONFIG_GENERIC_HWEIGHT=y CONFIG_GIGASET_BASE=m CONFIG_GIGASET_CAPI=y CONFIG_GIGASET_M101=m CONFIG_GIGASET_M105=m CONFIG_HAVE_COPY_THREAD_TLS=y CONFIG_HAVE_DEBUG_STACKOVERFLOW=y CONFIG_HAVE_GENERIC_GUP=y CONFIG_HAVE_IPIPE_SUPPORT=y CONFIG_HAVE_IPIPE_TRACER_SUPPORT=y CONFIG_HAVE_IRQ_EXIT_ON_IRQ_STACK=y CONFIG_HAVE_MEMBLOCK_NODE_MAP=y CONFIG_HAVE_MEMBLOCK=y CONFIG_HAVE_MEMORY_PRESENT=y CONFIG_HP100=m CONFIG_HSA_AMD=m CONFIG_HYSDN_CAPI=y CONFIG_HYSDN=m CONFIG_I2C_PARPORT_LIGHT=m CONFIG_INET6_XFRM_MODE_BEET=m CONFIG_INET6_XFRM_MODE_ROUTEOPTIMIZATION=m CONFIG_INET6_XFRM_MODE_TRANSPORT=m CONFIG_INET6_XFRM_MODE_TUNNEL=m CONFIG_INET_XFRM_MODE_BEET=m CONFIG_INET_XFRM_MODE_TRANSPORT=m CONFIG_INET_XFRM_MODE_TUNNEL=m CONFIG_INFINIBAND_CXGB3=m CONFIG_INFINIBAND_NES=m CONFIG_INTEL_MIC_BUS=m CONFIG_INTEL_MIC_HOST=m CONFIG_INTEL_MIC_X100_DMA=m CONFIG_INTEL_PMC_IPC=m CONFIG_IO_DELAY_TYPE_0X80=0 CONFIG_IO_DELAY_TYPE_0XED=1 CONFIG_IO_DELAY_TYPE_NONE=3 CONFIG_IO_DELAY_TYPE_UDELAY=2 CONFIG_IOMMU_HELPER=y CONFIG_IOSCHED_CFQ=y CONFIG_IOSCHED_DEADLINE=y CONFIG_IOSCHED_NOOP=y CONFIG_IPIPE_CORE_APIREV=2 CONFIG_IPIPE_CORE=y CONFIG_IPIPE_HAVE_HOSTRT=y CONFIG_IPIPE_TARGET_APIREV=2 CONFIG_IPIPE_WANT_APIREV_2=y CONFIG_IPIPE_WANT_PTE_PINNING=y CONFIG_IPIPE=y CONFIG_ISDN_CAPI_CAPI20=m CONFIG_ISDN_CAPI=m CONFIG_ISDN_DIVAS_BRIPCI=y CONFIG_ISDN_DIVAS_DIVACAPI=m CONFIG_ISDN_DIVAS=m CONFIG_ISDN_DIVAS_MAINT=m CONFIG_ISDN_DIVAS_PRIPCI=y CONFIG_ISDN_DIVAS_USERIDI=m CONFIG_ISDN_DRV_AVMB1_AVM_CS=m CONFIG_ISDN_DRV_AVMB1_B1PCI=m CONFIG_ISDN_DRV_AVMB1_B1PCIV4=y CONFIG_ISDN_DRV_AVMB1_B1PCMCIA=m CONFIG_ISDN_DRV_AVMB1_C4=m CONFIG_ISDN_DRV_AVMB1_T1PCI=m CONFIG_ISDN_DRV_GIGASET=m CONFIG_JOYSTICK_IFORCE_232=y CONFIG_JOYSTICK_IFORCE_USB=y CONFIG_KEYS_COMPAT=y CONFIG_LEDS_LT3593=m CONFIG_LOCALVERSION="-ipipe-9-xenomai-3.1-20201027" CONFIG_MAC80211_RC_MINSTREL_HT=y CONFIG_MAY_USE_DEVLINK=m CONFIG_MIC_COSM=m CONFIG_MICROCODE_OLD_INTERFACE=y CONFIG_MIGRATION=y CONFIG_MTD_M25P80=m CONFIG_MTD_NAND_BCH=m CONFIG_MTD_NAND_CAFE=m CONFIG_MTD_NAND_DISKONCHIP=m CONFIG_MTD_NAND_DISKONCHIP_PROBE_ADDRESS=0 CONFIG_MTD_NAND_ECC_BCH=y CONFIG_MTD_NAND_ECC=m CONFIG_MTD_NAND=m CONFIG_MTD_NAND_NANDSIM=m CONFIG_MTD_NAND_RICOH=m CONFIG_MTD_SM_COMMON=m CONFIG_MXM_WMI=m CONFIG_NET_CLS_IND=y CONFIG_NET_CLS_RSVP6=m CONFIG_NET_CLS_RSVP=m CONFIG_NET_CLS_TCINDEX=m CONFIG_NET_DEVLINK=m CONFIG_NET_VENDOR_HP=y CONFIG_NF_CT_PROTO_GRE=m CONFIG_NF_NAT_IPV4=m CONFIG_NF_NAT_IPV6=m CONFIG_NF_NAT_MASQUERADE_IPV4=y CONFIG_NF_NAT_MASQUERADE_IPV6=y CONFIG_NF_NAT_NEEDED=y CONFIG_NF_NAT_PROTO_DCCP=y CONFIG_NF_NAT_PROTO_GRE=m CONFIG_NF_NAT_PROTO_SCTP=y CONFIG_NF_NAT_PROTO_UDPLITE=y CONFIG_NO_BOOTMEM=y CONFIG_NODES_SPAN_OTHER_NODES=y CONFIG_NUMA_BALANCING=y CONFIG_OPTIMIZE_INLINING=y CONFIG_ORE=m CONFIG_PLUGIN_HOSTCC="" CONFIG_QUOTACTL_COMPAT=y CONFIG_REED_SOLOMON_DEC16=y CONFIG_REGMAP_I2C=y CONFIG_REGMAP_SPI=y CONFIG_RT_GROUP_SCHED=y CONFIG_RWSEM_XCHGADD_ALGORITHM=y CONFIG_SCIF_BUS=m CONFIG_SCIF=m CONFIG_SCSI_LPFC=m CONFIG_SCSI_OSD_DPRINT_SENSE=1 CONFIG_SCSI_OSD_INITIATOR=m CONFIG_SCSI_OSD_ULD=m CONFIG_SECURITY_APPARMOR_BOOTPARAM_VALUE=1 CONFIG_SENSORS_ADS1015=m CONFIG_SERIAL_8250_MOXA=m CONFIG_SGI_IOC4=m CONFIG_SND_SST_IPC_ACPI=m CONFIG_SND_SST_IPC=m CONFIG_THUNDERBOLT=m CONFIG_TRACING_EVENTS_GPIO=y CONFIG_USB_COMMON=y CONFIG_USB_HWA_HCD=m CONFIG_USB_SISUSBVGA_CON=y CONFIG_USB_WHCI_HCD=m CONFIG_USB_WUSB_CBAF=m CONFIG_USB_WUSB=m CONFIG_UWB_HWA=m CONFIG_UWB_I1480U=m CONFIG_UWB=m CONFIG_UWB_WHCI=m CONFIG_VHOST_RING=m CONFIG_VIDEO_USBVISION=m CONFIG_VOP_BUS=m CONFIG_VOP=m CONFIG_X86_DEV_DMA_OPS=y CONFIG_X86_INTEL_UMIP=y CONFIG_X86_INTERNODE_CACHE_SHIFT=6 CONFIG_XENO_OPT_HOSTRT=y CONFIG_XENO_OPT_STATS_IRQS=y CONFIG_XENO_REVISION_LEVEL=0 CONFIG_XENO_VERSION_MINOR=1 CONFIG_XENO_VERSION_STRING="3.1" CONFIG_XXHASH=m CONFIG_ZSTD_DECOMPRESS=m ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: schedule delay 15ms 2025-11-20 8:10 ` JerryJun @ 2025-11-20 18:53 ` Jan Kiszka 2025-11-26 3:20 ` JerryJun 0 siblings, 1 reply; 11+ messages in thread From: Jan Kiszka @ 2025-11-20 18:53 UTC (permalink / raw) To: JerryJun, xenomai@lists.linux.dev On 20.11.25 09:10, JerryJun wrote: > > Which configurations do you think could cause this delay? During this process, the hardware remained unchanged. We used the following configurations and attempted to disable certain features in the kernel boot parameters, but it didn't work: xenomai.smi=disabled intel_idle.max_cstate=0 intel_pstate=disable nox2apic > I cannot name a config option yet. But rather than comparing those, try to diff the structures of /sys/devices. Another shot into the dark: Boot the kernel with efi=noruntime. BTW, x2apic is harmless, actually better than [x]apic, but the latter should also not cause such issues. Jan > At 2025-11-19 00:00:12, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >> On 18.11.25 16:31, JerryJun wrote: >>> >>> Strangely enough, this delay wasn't present on the 4.19.89-ipip kernel - it only emerged after upgrading to 5.10.199-dovetail, despite no changes being made to the power management policy or thermal throttling settings during the update. Could this be related to potential instability in the HPET or TSC clock sources? And does upgrading to a new kernel version also necessitate a BIOS update? >>> >> >> Generally spoken, a newer kernel could always have changed something >> regarding how power tuning is done. Simple scenario: a kernel config >> switch was renaming or gained a new dependency that is not fulfill -> >> tuning feature is silently lost. >> >> Another reason for different behavior could be the enabling (maybe even >> by default) of a new feature that has unexpected side effects. You may >> check if there are new drivers active, new devices available. >> >> Jan >> >>> At 2025-11-14 13:38:36, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >>>> On 14.11.25 03:48, JerryJun wrote: >>>>> >>>>> We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. >>>>> include trace point events : >>>>> irq_vectors:call_function_entry >>>>> irq_vectors:call_function_exit >>>>> irq_vectors:call_function_single_entry >>>>> irq_vectors:call_function_single_exit >>>>> >>>> >>>> If there are no interrupt in that phase while, e.g., some timer >>>> interrupt should have occurred, then you should definitely check for >>>> hardware/firmware related delays that the OS cannot influence. Or for >>>> power-saving / thermal-throttling causes. >>>> >>>> Jan >>>> >>>>> 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >>>>>> On 13.11.25 05:00, JerryJun wrote: >>>>>>> >>>>>>> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >>>>>>> >>>>>> >>>>>> swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 >>>>>> swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 >>>>>> >>>>>> So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >>>>>> seeing that event in the trace. Furthermore, I always for get about >>>>>> that, it is useful to have irq_vectors events because those include >>>>>> timer irqs. But it is unlikely that we missed any in that gap because >>>>>> they tend to trigger activities like cobalt_core:cobalt_timer_expire. >>>>>> >>>>>> What is more likely here is that your hardware or firmware is not >>>>>> letting IRQs through. We could confirm that if the issue is reproducible >>>>>> while have function tracing enabled. That comes with high overhead, but >>>>>> the detailed result can tell us what the kernel did while there were no >>>>>> interrupts. >>>>>> >>>>>> There is also native tooling by the kernel to detect "hardware noise", >>>>>> see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >>>>>> nature, this noise would affect Xenomai equally. >>>>>> >>>>>> Jan >>>>>> >>>>>> -- >>>>>> Siemens AG, Foundational Technologies >>>>>> Linux Expert Center >>>> >>>> >>>> -- >>>> Siemens AG, Foundational Technologies >>>> Linux Expert Center >> >> -- >> Siemens AG, Foundational Technologies >> Linux Expert Center -- Siemens AG, Foundational Technologies Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re:Re: schedule delay 15ms 2025-11-20 18:53 ` Jan Kiszka @ 2025-11-26 3:20 ` JerryJun 0 siblings, 0 replies; 11+ messages in thread From: JerryJun @ 2025-11-26 3:20 UTC (permalink / raw) To: Jan Kiszka; +Cc: xenomai@lists.linux.dev We switched to another Intel platform and observed a gap of over 100ms(7574.499872->7574.631649). Could this be related to the ipipe->dovetail changes? swapper 0 [002] 7574.499869: irq:irq_pipeline_entry: irq=33027 swapper 0 [002] 7574.499870: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [002] 7574.499870: cobalt_core:cobalt_timer_expire: timer=0xffffc900006deef0 swapper 0 [002] 7574.499870: cobalt_core:cobalt_trace_pid: pid=2338, prio=85 swapper 0 [002] 7574.499871: cobalt_core:cobalt_timer_stop: timer=0xffffc900006deef0 swapper 0 [002] 7574.499871: irq:irq_handler_exit: irq=33027 ret=handled swapper 0 [002] 7574.499871: irq:irq_pipeline_exit: irq=33027 swapper 0 [002] 7574.499872: cobalt_core:cobalt_schedule: status=0x10000000 swapper 0 [002] 7574.499872: cobalt_core:cobalt_trace_pid: pid=0, prio=-1 swapper 0 [002] 7574.499872: cobalt_core:cobalt_timer_start: timer=0xffff888880136828([watchdog]) value=1000000000 interval=0 mode=0x0 swapper 0 [003] 7574.631649: irq:irq_pipeline_entry: irq=33027 rt-task1 2338 [002] 7574.631649: cobalt_core:cobalt_trace_pid: pid=2338, prio=85 swapper 0 [000] 7574.631649: irq:irq_pipeline_entry: irq=33027 swapper 0 [001] 7574.631650: irq:irq_pipeline_entry: irq=33027 swapper 0 [003] 7574.631650: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt rt-task1 2338 [002] 7574.631650: irq:irq_pipeline_entry: irq=33027 swapper 0 [000] 7574.631650: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [001] 7574.631650: irq:irq_handler_entry: irq=33027 name=Out-of-band LAPIC timer interrupt swapper 0 [003] 7574.631650: cobalt_core:cobalt_timer_expire: timer=0xffff8888801b6298At 2025-11-21 02:53:35, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >On 20.11.25 09:10, JerryJun wrote: >> >> Which configurations do you think could cause this delay? During this process, the hardware remained unchanged. We used the following configurations and attempted to disable certain features in the kernel boot parameters, but it didn't work: xenomai.smi=disabled intel_idle.max_cstate=0 intel_pstate=disable nox2apic >> > >I cannot name a config option yet. But rather than comparing those, try >to diff the structures of /sys/devices. > >Another shot into the dark: Boot the kernel with efi=noruntime. > >BTW, x2apic is harmless, actually better than [x]apic, but the latter >should also not cause such issues. > >Jan > >> At 2025-11-19 00:00:12, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >>> On 18.11.25 16:31, JerryJun wrote: >>>> >>>> Strangely enough, this delay wasn't present on the 4.19.89-ipip kernel - it only emerged after upgrading to 5.10.199-dovetail, despite no changes being made to the power management policy or thermal throttling settings during the update. Could this be related to potential instability in the HPET or TSC clock sources? And does upgrading to a new kernel version also necessitate a BIOS update? >>>> >>> >>> Generally spoken, a newer kernel could always have changed something >>> regarding how power tuning is done. Simple scenario: a kernel config >>> switch was renaming or gained a new dependency that is not fulfill -> >>> tuning feature is silently lost. >>> >>> Another reason for different behavior could be the enabling (maybe even >>> by default) of a new feature that has unexpected side effects. You may >>> check if there are new drivers active, new devices available. >>> >>> Jan >>> >>>> At 2025-11-14 13:38:36, "Jan Kiszka" <jan.kiszka@siemens.com> wrote: >>>>> On 14.11.25 03:48, JerryJun wrote: >>>>>> >>>>>> We added some trace event information, but from this gap point (6208.695948-> 6208.708726), it appears that the Cobalt kernel was frozen and no interrupt handling occurred. >>>>>> include trace point events : >>>>>> irq_vectors:call_function_entry >>>>>> irq_vectors:call_function_exit >>>>>> irq_vectors:call_function_single_entry >>>>>> irq_vectors:call_function_single_exit >>>>>> >>>>> >>>>> If there are no interrupt in that phase while, e.g., some timer >>>>> interrupt should have occurred, then you should definitely check for >>>>> hardware/firmware related delays that the OS cannot influence. Or for >>>>> power-saving / thermal-throttling causes. >>>>> >>>>> Jan >>>>> >>>>>> 在 2025-11-13 13:31:54，"Jan Kiszka" <jan.kiszka@siemens.com> 写道： >>>>>>> On 13.11.25 05:00, JerryJun wrote: >>>>>>>> >>>>>>>> We conducted tests on the kernel version v5.10.245-cip65-dovetail1. The test results are attached. During this period, we also performed latency tests, which showed a 10ms delay at 7174.313414 -> 7174.323086. irq 114 is net driver interrupt 。 >>>>>>>> >>>>>>> >>>>>>> swapper 0 [003] 7174.313414: irq:irq_pipeline_entry: irq=114 >>>>>>> swapper 0 [003] 7174.323086: irq:irq_pipeline_entry: irq=33027 >>>>>>> >>>>>>> So, that is the gap. Did you also turn on irq_pipeline_exit? I'm not >>>>>>> seeing that event in the trace. Furthermore, I always for get about >>>>>>> that, it is useful to have irq_vectors events because those include >>>>>>> timer irqs. But it is unlikely that we missed any in that gap because >>>>>>> they tend to trigger activities like cobalt_core:cobalt_timer_expire. >>>>>>> >>>>>>> What is more likely here is that your hardware or firmware is not >>>>>>> letting IRQs through. We could confirm that if the issue is reproducible >>>>>>> while have function tracing enabled. That comes with high overhead, but >>>>>>> the detailed result can tell us what the kernel did while there were no >>>>>>> interrupts. >>>>>>> >>>>>>> There is also native tooling by the kernel to detect "hardware noise", >>>>>>> see https://docs.kernel.org/tools/rtla/rtla-hwnoise.html. Due to its >>>>>>> nature, this noise would affect Xenomai equally. >>>>>>> >>>>>>> Jan >>>>>>> >>>>>>> -- >>>>>>> Siemens AG, Foundational Technologies >>>>>>> Linux Expert Center >>>>> >>>>> >>>>> -- >>>>> Siemens AG, Foundational Technologies >>>>> Linux Expert Center >>> >>> -- >>> Siemens AG, Foundational Technologies >>> Linux Expert Center > > >-- >Siemens AG, Foundational Technologies >Linux Expert Center ^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2025-11-26 3:20 UTC | newest] Thread overview: 11+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2025-11-12 6:09 schedule delay 15ms JerryJun 2025-11-12 8:23 ` Jan Kiszka 2025-11-13 4:00 ` JerryJun 2025-11-13 5:31 ` Jan Kiszka 2025-11-14 2:48 ` JerryJun 2025-11-14 5:38 ` Jan Kiszka 2025-11-18 15:31 ` JerryJun 2025-11-18 16:00 ` Jan Kiszka 2025-11-20 8:10 ` JerryJun 2025-11-20 18:53 ` Jan Kiszka 2025-11-26 3:20 ` JerryJun
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.