KDL while running git clone

[luroh]

hrev46712, gcc2, a two-CPU VBox machine running on an Intel CPU host. It seems reasonably easy to repeat here by git cloning the main Haiku repo. I hit it yesterday as well while doing the same thing.

PANIC: ASSERT FAILED (src/system/kernel/scheduler/scheduler_thread.h:397): system_time() - fWentSleep >= 0
Welcome to Kernel Debugging Land...
Thread 583 "git" running on CPU 1
stack trace for thread 583 "git"
    kernel stack: 0x813db000 to 0x813df000
      user stack: 0x71305000 to 0x72305000
frame               caller     <image>:function + offset
 0 813de4c8 (+  32) 8013fff2   <kernel_x86> arch_debug_stack_trace + 0x12
 1 813de4e8 (+  16) 8009ffdb   <kernel_x86> stack_trace_trampoline(NULL) + 0x0b
 2 813de4f8 (+  12) 80131cbe   <kernel_x86> arch_debug_call_with_fault_handler + 0x1b
 3 813de504 (+  48) 800a1b46   <kernel_x86> debug_call_with_fault_handler + 0x5a
 4 813de534 (+  64) 800a01f7   <kernel_x86> kernel_debugger_loop([34m0x80182037[0m [36m"PANIC: "[0m, [34m0x8017ea47[0m [36m"ASSERT FAILED (%s:%d): %s"[0m, [34m0x813de5e0[0m [36m"€ë€"[0m, int32: [34m1[0m) + 0x217
 5 813de574 (+  48) 800a0573   <kernel_x86> kernel_debugger_internal([34m0x80182037[0m [36m"PANIC: "[0m, [34m0x8017ea47[0m [36m"ASSERT FAILED (%s:%d): %s"[0m, [34m0x813de5e0[0m [36m"€ë€"[0m, int32: [34m1[0m) + 0x53
 6 813de5a4 (+  48) 800a1ece   <kernel_x86> panic + 0x3a
 7 813de5d4 (+ 112) 80091429   <kernel_x86> enqueue(BKernel::Thread*: [34m0x82214f90[0m, [34mtrue[0m) + 0x121
 8 813de644 (+  64) 800917b7   <kernel_x86> scheduler_enqueue_in_run_queue + 0xcf
 9 813de684 (+  64) 80054c57   <kernel_x86> ConditionVariable<[32m0x82340b54[0m>::_NotifyLocked([34mtrue[0m, int32: [34m0[0m) + 0xd7
10 813de6c4 (+  64) 80054b4e   <kernel_x86> ConditionVariable<[32m0x82340b54[0m>::_Notify([34mtrue[0m, int32: [34m0[0m) + 0x72
11 813de704 (+  64) 800c4831   <kernel_x86> IOSchedulerSimple<[32m0x82340b00[0m>::ScheduleRequest(IORequest*: [34m0x813de778[0m) + 0x251
12 813de744 (+ 224) 816a7472   <scsi_disk> das_write([34m0xd261cdd0[0m, int64: [34m22147072[0m, [34m0xd5342000[0m, [34m0x813de96c[0m) + 0xa2
13 813de824 (+  64) 800b2336   <kernel_x86> BPrivate::AbstractModuleDevice<[32m0x821e2c48[0m>::Write([34m0xd261cdd0[0m, int64: [34m22147072[0m, [34m0xd5342000[0m, [34m0x813de96c[0m) + 0x2a
14 813de864 (+  80) 800b7586   <kernel_x86> devfs_write(fs_volume*: [34m0x821d97e0[0m, fs_vnode*: [34m0x82344a30[0m, [34m0xd261ce80[0m, int64: [34m22147072[0m, [34m0xd5342000[0m, [34m0x813de96c[0m) + 0x126
15 813de8b4 (+  64) 800edd4f   <kernel_x86> file_write(file_descriptor*: [34m0xd261eda0[0m, int64: [34m22147072[0m, [34m0xd5342000[0m, [34m0x813de96c[0m) + 0x5b
16 813de8f4 (+  96) 800dab8f   <kernel_x86> _kern_write + 0x127
17 813de954 (+  64) 801524e4   <kernel_x86> write_pos + 0x28
18 813de994 (+  80) 8004a316   <kernel_x86> BlockWriter<[32m0x813dea68[0m>::_WriteBlock(cached_block*: [34m0xd77a19c8[0m) + 0x92
19 813de9e4 (+  48) 8004a163   <kernel_x86> BlockWriter<[32m0x813dea68[0m>::Write(hash_iterator*: NULL, [34mtrue[0m) + 0x7b
20 813dea14 (+ 400) 8004cf32   <kernel_x86> cache_sync_transaction + 0x192
21 813deba4 (+  48) 81773081   <bfs> Journal<[32m0xd2670aa0[0m>::_TransactionDone([34mtrue[0m) + 0xc5
22 813debd4 (+  48) 81772ebe   <bfs> Journal<[32m0xd2670aa0[0m>::Unlock(Transaction*: [34m0x813dec44[0m, [34mtrue[0m) + 0x4e
23 813dec04 (+  80) 8177a1d8   <bfs> bfs_create(fs_volume*: [34m0xd261e080[0m, fs_vnode*: [34m0xd8c45e78[0m, [34m0x813dedf4[0m [36m"Jamfile"[0m, int32: [34m769[0m, int32: [34m420[0m, [34m0x813dec9c[0m, [34m0x813deca0[0m) + 0x1c0
24 813dec54 (+ 352) 800ed470   <kernel_x86> create_vnode(vnode*: [34m0xd8c45e78[0m, [34m0x813dedf4[0m [36m"Jamfile"[0m, int32: [34m769[0m, int32: [34m420[0m, [34mfalse[0m) + 0x1b8
25 813dedb4 (+ 320) 800ed93a   <kernel_x86> file_create(int32: [34m-1[0m, [34m0xd2518238[0m [36m"src"[0m, int32: [34m769[0m, int32: [34m420[0m, [34mfalse[0m) + 0x5a
26 813deef4 (+  80) 800f3998   <kernel_x86> _user_open + 0xc0
27 813def44 (+ 100) 801348ff   <kernel_x86> handle_syscall + 0xdc
user iframe at 0x813defa8 (end = 0x813df000)
 eax 0x69          ebx 0x1ab2928      ecx 0x723042c8  edx 0x62136114
 esi 0xc762e0      edi 0x1bfad5b8     ebp 0x723042f4  esp 0x813defdc
 eip 0x62136114 eflags 0x203202  user esp 0x723042c8
 vector: 0x63, error code: 0x0
28 813defa8 (+   0) 62136114   <commpage> commpage_syscall + 0x04
29 723042f4 (+  48) 00b7a86b   <git> launch_editor (nearest) + 0x437
30 72304324 (+  48) 00b7a92d   <git> launch_editor (nearest) + 0x4f9
31 72304354 (+  48) 00b7a9a9   <git> launch_editor (nearest) + 0x575
32 72304384 (+ 176) 00b7aaa2   <git> launch_editor (nearest) + 0x66e
33 72304434 (+ 160) 00b7aee1   <git> checkout_entry + 0x171
34 723044d4 (+  80) 00bd9de1   <git> setup_unpack_trees_porcelain (nearest) + 0x805
35 72304524 (+ 128) 00bdb37e   <git> unpack_trees + 0x3a6
36 723045a4 (+ 496) 00af2ddf   <git> cmd_clean (nearest) + 0x228f
37 72304794 (+ 240) 00af3db1   <git> cmd_clone + 0xbb9
38 72304884 (+ 160) 00ad7b58   <git> _start (nearest) + 0xb28
39 72304924 (+  60) 00ad7c9a   <git> _start (nearest) + 0xc6a
40 72304960 (+  48) 00ad7db6   <git> _start (nearest) + 0xd86
41 72304990 (+  48) 00ad7f90   <git> main + 0x1a8
42 723049c0 (+  48) 00ad708b   <git> _start + 0x5b
43 723049f0 (+  48) 00f2202e   </boot/system/runtime_loader@0x00f12000> <unknown> + 0x1002e
44 72304a20 (+   0) 62136250   <commpage> commpage_thread_exit + 0x00

[oco]

I got a similar error with a 2 CPUs virtualbox machine, with, maybe, a simpler scenario : booting a hrev46706 nightly ISO image. I have posted a serial trace as part of a comment on bug #8345 https://dev.haiku-os.org/attachment/ticket/8345/port.2.txt.

A 4 CPUs virtual machine gave me a different error, closer to #8345.

[pdziepak]

Should be fixed in hrev46718. Please confirm.

[luroh]

hrev46723 just crashed on the third 'git clone', but with a different stack trace. Let me know if you'd like me to file a separate ticket.

PANIC: ASSERT FAILED (src/system/kernel/scheduler/scheduler_cpu.cpp:438): newKey >= 0
Welcome to Kernel Debugging Land...
Thread 174 "scsi scheduler 3" running on CPU 1
stack trace for thread 174 "scsi scheduler 3"
    kernel stack: 0x8188b000 to 0x8188f000
frame               caller     <image>:function + offset
 0 8188eba8 (+  32) 8013ffe2   <kernel_x86> arch_debug_stack_trace + 0x12
 1 8188ebc8 (+  16) 8009ffcb   <kernel_x86> stack_trace_trampoline(NULL) + 0x0b
 2 8188ebd8 (+  12) 80131cae   <kernel_x86> arch_debug_call_with_fault_handler + 0x1b
 3 8188ebe4 (+  48) 800a1b36   <kernel_x86> debug_call_with_fault_handler + 0x5a
 4 8188ec14 (+  64) 800a01e7   <kernel_x86> kernel_debugger_loop([34m0x80181f77[0m [36m"PANIC: "[0m, [34m0x8017f247[0m [36m"ASSERT FAILED (%s:%d): %s"[0m, [34m0x8188ecc0[0m [36m"`ö€¶"[0m, int32: [34m1[0m) + 0x217
 5 8188ec54 (+  48) 800a0563   <kernel_x86> kernel_debugger_internal([34m0x80181f77[0m [36m"PANIC: "[0m, [34m0x8017f247[0m [36m"ASSERT FAILED (%s:%d): %s"[0m, [34m0x8188ecc0[0m [36m"`ö€¶"[0m, int32: [34m1[0m) + 0x53
 6 8188ec84 (+  48) 800a1ebe   <kernel_x86> panic + 0x3a
 7 8188ecb4 (+  64) 800960ed   <kernel_x86> Scheduler::CoreEntry<[32m0x8214bc44[0m>::UpdateLoad(int32: [34m-534[0m) + 0x121
 8 8188ecf4 (+ 208) 800924b8   <kernel_x86> reschedule(int32: [34m6[0m) + 0x598
 9 8188edc4 (+  48) 80092fb9   <kernel_x86> scheduler_reschedule + 0x61
10 8188edf4 (+  96) 800850c2   <kernel_x86> thread_block + 0x10a
11 8188ee54 (+  48) 80053ff9   <kernel_x86> ConditionVariableEntry<[32m0x8188eeb4[0m>::Wait(uint32: [34m0x1[0m ([34m1[0m), int64: [34m0[0m) + 0x12d
12 8188ee84 (+  80) 800c5683   <kernel_x86> IOSchedulerSimple<[32m0x82340b00[0m>::_NextActiveRequestOwner(IORequestOwner&: [34m0x8188ef28[0m, [34m0x8188ef2c[0m) + 0x18b
13 8188eed4 (+ 192) 800c5c25   <kernel_x86> IOSchedulerSimple<[32m0x82340b00[0m>::_Scheduler([34m0xcccccccc[0m) + 0x22d
14 8188ef94 (+  32) 800c63de   <kernel_x86> IOSchedulerSimple<[32m0x82340b00[0m>::_SchedulerThread([34m0xcccccccc[0m) + 0x12
15 8188efb4 (+  48) 80080543   <kernel_x86> common_thread_entry([34m0x8188eff0[0m) + 0x3b

[oco]

Tested with nightly ISO hrev46720, i have the same error as luroh in my test case (booting from the ISO). Sometimes it crash before or after selecting "boot to Desktop".

[pdziepak]

I managed to reproduce the problem and it looks like hrev46726 (actually, the other commit in that push) fixes the bug. Please confirm.

[luroh]

Looks good here; five 'git clone' without any incident, just another #10442 crash when shutting down.