From: "Chen, Hongzhan" <hongzhan.chen@intel.com>
To: Philippe Gerum <rpm@xenomai.org>
Cc: "xenomai@xenomai.org" <xenomai@xenomai.org>
Subject: RE: gdb test failure debug status update
Date: Fri, 30 Apr 2021 08:07:19 +0000 [thread overview]
Message-ID: <DM5PR11MB18527EA509FB99BF50D1ACFFF25E9@DM5PR11MB1852.namprd11.prod.outlook.com> (raw)
In-Reply-To: <875z042odb.fsf@xenomai.org>
>-----Original Message-----
>From: Philippe Gerum <rpm@xenomai.org>
>Sent: Friday, April 30, 2021 4:01 PM
>To: Chen, Hongzhan <hongzhan.chen@intel.com>
>Cc: xenomai@xenomai.org
>Subject: Re: gdb test failure debug status update
>
>
>Philippe Gerum <rpm@xenomai.org> writes:
>
>> Chen, Hongzhan <hongzhan.chen@intel.com> writes:
>>
>>> The final xnthread_relaxed call path is like this asm_sysv_apic_timer_interrupt ->handle_irq_pipelined_finish
>>> ->dovetail_call_mayday ->handle_oob_mayday>xnthread_relax.
>>> That means that handle_irq_pipelined_finish is called under OOB condition of arch_pipeline_entry in
>>> arch/x86/kernel/irq_pipeline.c. Does that means that kernel entry/exit code is never called after return from
>>> xnthread_relax to handle_irq_pipelined_finish then to asm_sysv_apic_timer_interrupt? Even I enforce to
>>> call dovetail_request_ucall before calling final xnthread_relax system would not try to switch back to primary mode
>>> because kernel exit code is never called in this case?
>>>
>>
>> The IRQ frame is indeed kept from unwinding until the preempted task
>> context returns from irq_exit_pipeline(), which branches to the Cobalt
>> rescheduling procedure. From the Dovetail interface POV,
>> irq_exit_pipeline() is called by handle_irq_pipelined_finish() to allow
>> the companion core to perform post-IRQ chores, such as running its own
>> rescheduling procedure.
>>
>> IOW, if task @foo is preempted by an IRQ, then suspended in oob context
>> as a result of what the interrupt handler just did for it (e.g. raising
>> XNDBGSTOP, XNRELAX, XNPEND, XNSUSP in its state), then
>> handle_irq_pipelined_finish()->irq_exit_pipeline()->xnsched_run() will
>> cause the @foo context to switch away, effectively preventing
>> handle_irq_pipelined_finish() to return, until @foo resumes execution
> eventually.
>
> The underlying issue I'd like to understand, is why do we have a mayday
> condition raised in the context of this test in the first place? That
> may be the root of the issue, the mayday and synchronous-bp handling
> code may not cope that well.
>
> So, question to address first: who ends up calling
> dovetail_call_mayday(), detecting that the underlying task went south?
> And why that?
>
>Possibly a caller of __xnthread_kick() is causing that, e.g.
>handle_sigwake_event -> __xnthread_kick.
Yes, that is right. Like in line gdb-2495 [000] ...1 61513.836529: sys_tkill(pid: 9c3, sig: 13) of log [4] ,
Sys_tkill would finally call __xnthread_kick to set MAYDAY through handle_sigwake_event by gdb and then
Smokey thread is to handle mayday. I also get ftrace log for ipipe-5.4-xenomai, it has same caller.
>
>--
>Philippe.
>
[4]:
gdb-2495 [000] d..3 61513.834825: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2499 next_prio=98
smokey-2499 [000] ...1 61513.834827: cobalt_handle_ptrace_cont: pid=2499 state=0x4488c0 info=0x200
smokey-2499 [000] d..1 61513.834828: cobalt_handle_user_return: pid=2499 state=0x4488c0 info=0x200
smokey-2499 [000] d..1 61513.834828: cobalt_shadow_gohard: state=0x4488c0 info=0x0
smokey-2499 [000] d..3 61513.834830: sched_stat_wait: comm=gdb pid=2495 delay=8017 [ns]
smokey-2499 [000] d..3 61513.834831: sched_switch: prev_comm=smokey prev_pid=2499 prev_prio=98 prev_state=S ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] *..3 61513.834831: cobalt_thread_resume: name=smokey pid=2499 mask=0x80
gdb-2495 [000] *..3 61513.834832: cobalt_trace_pid: pid=2499, prio=1
gdb-2495 [000] *..3 61513.834832: cobalt_thread_resume: name=smokey pid=2499 mask=0x400000
gdb-2495 [000] *..3 61513.834832: cobalt_trace_pid: pid=2499, prio=1
gdb-2495 [000] *.~3 61513.834833: cobalt_schedule: status=0x10000000
gdb-2495 [000] *.~3 61513.834833: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] *.~3 61513.834833: cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=smokey next_pid=2499 next_prio=1
smokey-2499 [000] d.~3 61513.834835: cobalt_shadow_hardened: state=0x48040 info=0x0
smokey-2499 [000] d.~3 61513.834836: cobalt_head_sysentry: syscall=sem_init
smokey-2499 [000] d.~3 61513.834839: cobalt_psem_init: sem=0x4e(anon) flags=0x0() value=0
smokey-2499 [000] d.~3 61513.834839: cobalt_head_sysexit: result=0
smokey-2499 [000] d.~3 61513.834848: cobalt_shadow_gorelax: reason=syscall
smokey-2499 [000] d.~3 61513.834848: cobalt_lostage_request: request=wakeup pid=2499 comm=smokey
smokey-2499 [000] *.~3 61513.834848: cobalt_thread_suspend: pid=2499 mask=0x80 timeout=0 timeout_mode=0 wchan=0000000000000000
smokey-2499 [000] *.~3 61513.834849: cobalt_schedule: status=0x10000000
smokey-2499 [000] *.~3 61513.834849: cobalt_trace_pid: pid=2499, prio=1
smokey-2499 [000] *.~3 61513.834849: cobalt_switch_context: prev_name=smokey prev_pid=2499 prev_prio=1 prev_state=0x480c0 ==> next_name=ROOT/0 next_pid=0 next_prio=-1
gdb-2495 [000] *.~3 61513.834850: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] d.h3 61513.834851: irq_handler_entry: irq=120 name=in-band work
gdb-2495 [000] d.h3 61513.834852: cobalt_lostage_wakeup: pid=2499 comm=smokey
gdb-2495 [000] d.h5 61513.834852: sched_waking: comm=smokey pid=2499 prio=98 target_cpu=000
gdb-2495 [000] dNh6 61513.834853: sched_wakeup: comm=smokey pid=2499 prio=98 target_cpu=000
gdb-2495 [000] dNh3 61513.834853: irq_handler_exit: irq=120 ret=handled
gdb-2495 [000] dN.3 61513.834854: sched_stat_runtime: comm=gdb pid=2495 runtime=23565 [ns] vruntime=300514015543 [ns]
gdb-2495 [000] d..3 61513.834855: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2499 next_prio=98
smokey-2499 [000] ...1 61513.834856: cobalt_shadow_relaxed: state=0x480c0 info=0x0
smokey-2499 [000] ...1 61513.834857: sys_sched_get_priority_min(policy: 1)
smokey-2499 [000] ...1 61513.834857: sys_sched_get_priority_min -> 0x1
smokey-2499 [000] ...1 61513.834859: sys_sched_get_priority_max(policy: 1)
smokey-2499 [000] ...1 61513.834859: sys_sched_get_priority_max -> 0x63
smokey-2499 [000] ..~1 61513.834862: cobalt_head_sysentry: syscall=thread_getschedparam_ex
smokey-2499 [000] ...1 61513.834862: cobalt_root_sysentry: syscall=thread_getschedparam_ex
smokey-2499 [000] ...1 61513.834863: cobalt_pthread_getschedparam: pth=000000008d36be1c policy=fifo param={ priority=1 }
smokey-2499 [000] ...1 61513.834864: cobalt_root_sysexit: result=0
smokey-2499 [000] ...1 61513.834872: sys_mmap(addr: 0, len: 11000, prot: 0, flags: 20022, fd: ffffffff, off: 0)
smokey-2499 [000] ...1 61513.834877: sys_mmap -> 0x7ffff67b9000
smokey-2499 [000] ...1 61513.834878: sys_mprotect(start: 7ffff67ba000, len: 10000, prot: 3)
smokey-2499 [000] ...1 61513.834906: sys_mprotect -> 0x0
smokey-2499 [000] ...1 61513.834909: sys_clone(clone_flags: 3d0f00, newsp: 7ffff67c8fb0, parent_tidptr: 7ffff67c99d0, child_tidptr: 7ffff67c99d0, tls: 7ffff67c9700)
smokey-2499 [000] ...1 61513.834923: task_newtask: pid=2504 comm=smokey clone_flags=3d0f00 oom_score_adj=0
smokey-2499 [000] ...1 61513.834923: sched_process_fork: comm=smokey pid=2499 child_comm=smokey child_pid=2504
smokey-2499 [000] d..3 61513.834925: sched_wakeup_new: comm=smokey pid=2504 prio=98 target_cpu=000
smokey-2499 [000] d..3 61513.834928: signal_generate: sig=17 errno=0 code=4 comm=gdb pid=2495 grp=1 res=0
smokey-2499 [000] d..3 61513.834931: sched_switch: prev_comm=smokey prev_pid=2499 prev_prio=98 prev_state=t ==> next_comm=smokey next_pid=2504 next_prio=98
hi-thread-2504 [000] ...1 61513.834932: sys_clone -> 0x0
hi-thread-2504 [000] d..3 61513.834934: signal_generate: sig=17 errno=0 code=4 comm=gdb pid=2495 grp=1 res=2
hi-thread-2504 [000] d..3 61513.834935: sched_stat_wait: comm=gdb pid=2495 delay=82002 [ns]
hi-thread-2504 [000] d..3 61513.834936: sched_switch: prev_comm=smokey prev_pid=2504 prev_prio=98 prev_state=t ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] d..2 61513.834937: signal_deliver: sig=17 errno=0 code=4 sa_handler=5585fdc414d0 sa_flags=14000000
gdb-2495 [000] ...1 61513.834940: sys_read(fd: f, buf: 7ffe8b2a71e7, count: 1)
gdb-2495 [000] ...1 61513.834943: sys_read -> 0x1
gdb-2495 [000] ...1 61513.834943: sys_read(fd: f, buf: 7ffe8b2a71e7, count: 1)
gdb-2495 [000] ...1 61513.834944: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.834944: sys_write(fd: 10, buf: 5585fe0354b1, count: 1)
gdb-2495 [000] ...1 61513.834946: sys_write -> 0x1
gdb-2495 [000] ...1 61513.834947: sys_rt_sigreturn()
gdb-2495 [000] ...1 61513.834953: sys_read(fd: 9, buf: 7ffe8b2a82e7, count: 1)
gdb-2495 [000] ...1 61513.834953: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.834955: sys_poll(ufds: 5585fe898350, nfds: 4, timeout_msecs: 0)
gdb-2495 [000] ...1 61513.834956: sys_poll -> 0x1
gdb-2495 [000] ...1 61513.834957: sys_read(fd: f, buf: 7ffe8b2a7f27, count: 1)
gdb-2495 [000] ...1 61513.834958: sys_read -> 0x1
gdb-2495 [000] ...1 61513.834959: sys_read(fd: f, buf: 7ffe8b2a7f27, count: 1)
gdb-2495 [000] ...1 61513.834960: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.834961: sys_rt_sigprocmask(how: 0, nset: 5585fe2d4a60, oset: 7ffe8b2a7e60, sigsetsize: 8)
gdb-2495 [000] ...1 61513.834961: sys_rt_sigprocmask -> 0x0
gdb-2495 [000] ...1 61513.834962: sys_wait4(upid: ffffffff, stat_addr: 7ffe8b2a7db4, options: 40000001, ru: 0)
gdb-2495 [000] ...1 61513.834962: sched_process_wait: comm=gdb pid=0 prio=120
gdb-2495 [000] ...1 61513.834964: sys_wait4 -> 0x9c3
gdb-2495 [000] ...1 61513.834965: sys_ptrace(request: 4201, pid: 9c3, addr: 0, data: 7ffe8b2a7d08)
gdb-2495 [000] d..3 61513.834966: sched_wait_task: comm=smokey pid=2499 prio=98
gdb-2495 [000] ...1 61513.834967: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.834967: sys_wait4(upid: 9c8, stat_addr: 7ffe8b2a7cfc, options: 40000000, ru: 0)
gdb-2495 [000] ...1 61513.834968: sched_process_wait: comm=gdb pid=2504 prio=120
gdb-2495 [000] ...1 61513.834969: sys_wait4 -> 0x9c8
gdb-2495 [000] ...1 61513.834972: sys_ptrace(request: 1, pid: 9c3, addr: 7ffff777f370, data: 7ffe8b2a7578)
gdb-2495 [000] d..3 61513.834972: sched_wait_task: comm=smokey pid=2499 prio=98
gdb-2495 [000] ...1 61513.834975: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.834976: sys_ptrace(request: 3, pid: 9c8, addr: a8, data: 7ffe8b2a78d8)
gdb-2495 [000] d..3 61513.834977: sched_wait_task: comm=smokey pid=2504 prio=98
gdb-2495 [000] ...1 61513.834977: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.834979: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a6de0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.834989: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.834990: sys_pread64(fd: 12, buf: 7ffe8b2a7130, count: 900, pos: 7ffff67c9700)
gdb-2495 [000] ...1 61513.834992: sys_pread64 -> 0x900
gdb-2495 [000] ...1 61513.834993: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.834994: sys_close -> 0x0
gdb-2495 [000] ...1 61513.835010: sys_ptrace(request: 1, pid: 9c3, addr: 7ffff777f370, data: 7ffe8b2a7578)
gdb-2495 [000] d..3 61513.835011: sched_wait_task: comm=smokey pid=2499 prio=98
gdb-2495 [000] ...1 61513.835012: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.835013: sys_ptrace(request: 3, pid: 9c3, addr: a8, data: 7ffe8b2a78d8)
gdb-2495 [000] d..3 61513.835013: sched_wait_task: comm=smokey pid=2499 prio=98
gdb-2495 [000] ...1 61513.835014: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.835015: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a6de0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.835022: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.835022: sys_pread64(fd: 12, buf: 7ffe8b2a7130, count: 900, pos: 7ffff758f740)
gdb-2495 [000] ...1 61513.835025: sys_pread64 -> 0x900
gdb-2495 [000] ...1 61513.835025: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.835026: sys_close -> 0x0
gdb-2495 [000] ...1 61513.835031: sys_wait4(upid: ffffffff, stat_addr: 7ffe8b2a7db4, options: 40000001, ru: 0)
gdb-2495 [000] ...1 61513.835032: sched_process_wait: comm=gdb pid=0 prio=120
gdb-2495 [000] ...1 61513.835033: sys_wait4 -> 0x0
gdb-2495 [000] ...1 61513.835036: sys_ptrace(request: c, pid: 9c8, addr: 0, data: 7ffe8b2a6ef0)
gdb-2495 [000] d..3 61513.835037: sched_wait_task: comm=smokey pid=2504 prio=98
gdb-2495 [000] ...1 61513.835039: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.835043: sys_ptrace(request: 6, pid: 9c8, addr: 388, data: 0)
gdb-2495 [000] d..3 61513.835044: sched_wait_task: comm=smokey pid=2504 prio=98
gdb-2495 [000] ...1 61513.835044: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.835045: sys_ptrace(request: 7, pid: 9c8, addr: 1, data: 0)
gdb-2495 [000] d..3 61513.835046: sched_wait_task: comm=smokey pid=2504 prio=98
gdb-2495 [000] d..3 61513.835047: sched_waking: comm=smokey pid=2504 prio=98 target_cpu=000
gdb-2495 [000] dN.4 61513.835048: sched_wakeup: comm=smokey pid=2504 prio=98 target_cpu=000
gdb-2495 [000] .N.1 61513.835048: sys_ptrace -> 0x0
gdb-2495 [000] dN.3 61513.835050: sched_stat_runtime: comm=gdb pid=2495 runtime=112561 [ns] vruntime=300514128104 [ns]
gdb-2495 [000] d..3 61513.835051: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2504 next_prio=98
hi-thread-2504 [000] ...1 61513.835055: sys_set_robust_list(head: 7ffff67c99e0, len: 18)
hi-thread-2504 [000] ...1 61513.835055: sys_set_robust_list -> 0x0
hi-thread-2504 [000] ...1 61513.835056: sys_futex(uaddr: 7ffff67c9d18, op: 80, val: 2, utime: 0, uaddr2: 7ffff67c9700, val3: 7ffff67c9700)
hi-thread-2504 [000] d..3 61513.835059: sched_stat_wait: comm=gdb pid=2495 delay=10883 [ns]
hi-thread-2504 [000] d..3 61513.835060: sched_switch: prev_comm=smokey prev_pid=2504 prev_prio=98 prev_state=S ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] ...1 61513.835063: sys_ptrace(request: c, pid: 9c3, addr: 0, data: 7ffe8b2a6ef0)
gdb-2495 [000] d..3 61513.835064: sched_wait_task: comm=smokey pid=2499 prio=98
gdb-2495 [000] ...1 61513.835065: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.835068: sys_ptrace(request: 7, pid: 9c3, addr: 1, data: 0)
gdb-2495 [000] d..3 61513.835069: sched_wait_task: comm=smokey pid=2499 prio=98
gdb-2495 [000] d..3 61513.835069: sched_waking: comm=smokey pid=2499 prio=98 target_cpu=000
gdb-2495 [000] dN.4 61513.835070: sched_wakeup: comm=smokey pid=2499 prio=98 target_cpu=000
gdb-2495 [000] .N.1 61513.835071: sys_ptrace -> 0x0
gdb-2495 [000] dN.3 61513.835071: sched_stat_runtime: comm=gdb pid=2495 runtime=12210 [ns] vruntime=300514140314 [ns]
gdb-2495 [000] d..3 61513.835072: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2499 next_prio=98
smokey-2499 [000] ...1 61513.835073: cobalt_handle_ptrace_cont: pid=2499 state=0x480c0 info=0x0
smokey-2499 [000] ...1 61513.835074: sys_clone -> 0x9c8
smokey-2499 [000] ...1 61513.835075: sys_sched_setaffinity(pid: 9c8, len: 80, user_mask_ptr: 55555563e7c0)
smokey-2499 [000] ...1 61513.835077: sys_sched_setaffinity -> 0x0
smokey-2499 [000] ...1 61513.835077: sys_futex(uaddr: 7ffff67c9d18, op: 81, val: 1, utime: 7ffff67c99d0, uaddr2: 0, val3: 7ffff67c9700)
smokey-2499 [000] d..3 61513.835078: sched_waking: comm=smokey pid=2504 prio=98 target_cpu=000
smokey-2499 [000] d..4 61513.835079: sched_wakeup: comm=smokey pid=2504 prio=98 target_cpu=000
smokey-2499 [000] ...1 61513.835080: sys_futex -> 0x1
smokey-2499 [000] ...1 61513.835086: sys_futex(uaddr: 7fffffffe828, op: 189, val: 0, utime: 7fffffffe780, uaddr2: 0, val3: ffffffff)
smokey-2499 [000] d..3 61513.835089: sched_switch: prev_comm=smokey prev_pid=2499 prev_prio=98 prev_state=S ==> next_comm=smokey next_pid=2504 next_prio=98
hi-thread-2504 [000] ...1 61513.835090: sys_futex -> 0x0
hi-thread-2504 [000] ...1 61513.835090: sys_futex(uaddr: 7ffff67c9d18, op: 81, val: 1, utime: 7ffff67c99d0, uaddr2: 7ffff67c9700, val3: 7ffff67c9700)
hi-thread-2504 [000] ...1 61513.835091: sys_futex -> 0x0
hi-thread-2504 [000] ...1 61513.835092: sys_sched_setscheduler(pid: 9c8, policy: 1, param: 7ffff67c8e70)
hi-thread-2504 [000] ...1 61513.835095: sys_sched_setscheduler -> 0x0
hi-thread-2504 [000] ..~1 61513.835096: cobalt_head_sysentry: syscall=thread_create
hi-thread-2504 [000] ...1 61513.835097: cobalt_root_sysentry: syscall=thread_create
hi-thread-2504 [000] ...1 61513.835098: cobalt_pthread_create: pth=00000000ba35a01d policy=fifo param={ priority=2 }
hi-thread-2504 [000] ...1 61513.835099: cobalt_timer_migrate: timer=000000004d21df54 cpu=0
hi-thread-2504 [000] ...1 61513.835100: cobalt_timer_migrate: timer=00000000c1301853 cpu=0
hi-thread-2504 [000] ...1 61513.835101: cobalt_thread_set_current_prio: thread=00000000e9fda3c4 pid=-1 prio=2
hi-thread-2504 [000] ...1 61513.835102: cobalt_thread_init: thread=00000000e9fda3c4 name=smokey flags=0x48000 class=rt prio=2
hi-thread-2504 [000] ...1 61513.835104: cobalt_shadow_map: thread=00000000e9fda3c4 pid=2504 prio=2
hi-thread-2504 [000] D..1 61513.835104: cobalt_thread_suspend: pid=2504 mask=0x80 timeout=0 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] D..1 61513.835105: cobalt_thread_start: pid=2504 state=0x480d0 info=0x0
hi-thread-2504 [000] D..1 61513.835105: cobalt_thread_resume: name=smokey pid=2504 mask=0x10
hi-thread-2504 [000] D..1 61513.835106: cobalt_trace_pid: pid=2504, prio=2
hi-thread-2504 [000] ...1 61513.835106: cobalt_trace_pid: pid=2504, prio=2
hi-thread-2504 [000] ...1 61513.835107: cobalt_shadow_gohard: state=0x480c0 info=0x0
hi-thread-2504 [000] d..3 61513.835108: sched_stat_wait: comm=gdb pid=2495 delay=37231 [ns]
hi-thread-2504 [000] d..3 61513.835109: sched_switch: prev_comm=smokey prev_pid=2504 prev_prio=97 prev_state=S ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] *..3 61513.835109: cobalt_thread_resume: name=smokey pid=2504 mask=0x80
gdb-2495 [000] *..3 61513.835110: cobalt_trace_pid: pid=2504, prio=2
gdb-2495 [000] *.~3 61513.835110: cobalt_schedule: status=0x10000000
gdb-2495 [000] *.~3 61513.835110: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] *.~3 61513.835111: cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=smokey next_pid=2504 next_prio=2
hi-thread-2504 [000] d.~3 61513.835112: cobalt_shadow_hardened: state=0x48040 info=0x0
hi-thread-2504 [000] d.~3 61513.835112: cobalt_root_sysexit: result=0
hi-thread-2504 [000] d.~3 61513.835113: cobalt_head_sysentry: syscall=get_current
hi-thread-2504 [000] d.~3 61513.835113: cobalt_head_sysexit: result=0
hi-thread-2504 [000] d.~3 61513.835116: cobalt_shadow_gorelax: reason=syscall
hi-thread-2504 [000] d.~3 61513.835117: cobalt_lostage_request: request=wakeup pid=2504 comm=smokey
hi-thread-2504 [000] *.~3 61513.835117: cobalt_thread_suspend: pid=2504 mask=0x80 timeout=0 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] *.~3 61513.835117: cobalt_schedule: status=0x10000000
hi-thread-2504 [000] *.~3 61513.835118: cobalt_trace_pid: pid=2504, prio=2
hi-thread-2504 [000] *.~3 61513.835118: cobalt_switch_context: prev_name=smokey prev_pid=2504 prev_prio=2 prev_state=0x480c0 ==> next_name=ROOT/0 next_pid=0 next_prio=-1
gdb-2495 [000] *.~3 61513.835119: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] d.h3 61513.835120: irq_handler_entry: irq=120 name=in-band work
gdb-2495 [000] d.h3 61513.835120: cobalt_lostage_wakeup: pid=2504 comm=smokey
gdb-2495 [000] d.h5 61513.835120: sched_waking: comm=smokey pid=2504 prio=97 target_cpu=000
gdb-2495 [000] dNh6 61513.835121: sched_wakeup: comm=smokey pid=2504 prio=97 target_cpu=000
gdb-2495 [000] dNh3 61513.835122: irq_handler_exit: irq=120 ret=handled
gdb-2495 [000] dN.3 61513.835122: sched_stat_runtime: comm=gdb pid=2495 runtime=13441 [ns] vruntime=300514153755 [ns]
gdb-2495 [000] d..3 61513.835123: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2504 next_prio=97
hi-thread-2504 [000] ...1 61513.835124: cobalt_shadow_relaxed: state=0x480c0 info=0x0
hi-thread-2504 [000] ...1 61513.835125: sys_futex(uaddr: 7fffffffe828, op: 81, val: 1, utime: 0, uaddr2: 7ffff67c8e74, val3: 7fffffffe828)
hi-thread-2504 [000] d..3 61513.835126: sched_waking: comm=smokey pid=2499 prio=98 target_cpu=000
hi-thread-2504 [000] d..4 61513.835126: sched_wakeup: comm=smokey pid=2499 prio=98 target_cpu=000
hi-thread-2504 [000] ...1 61513.835127: sys_futex -> 0x1
hi-thread-2504 [000] ..~1 61513.835128: cobalt_head_sysentry: syscall=migrate
hi-thread-2504 [000] ...1 61513.835128: cobalt_root_sysentry: syscall=migrate
hi-thread-2504 [000] ...1 61513.835128: cobalt_shadow_gohard: state=0x480c0 info=0x0
hi-thread-2504 [000] d..3 61513.835130: sched_switch: prev_comm=smokey prev_pid=2504 prev_prio=97 prev_state=S ==> next_comm=smokey next_pid=2499 next_prio=98
smokey-2499 [000] *..3 61513.835130: cobalt_thread_resume: name=smokey pid=2504 mask=0x80
smokey-2499 [000] *..3 61513.835130: cobalt_trace_pid: pid=2504, prio=2
smokey-2499 [000] *.~3 61513.835131: cobalt_schedule: status=0x10000000
smokey-2499 [000] *.~3 61513.835131: cobalt_trace_pid: pid=2499, prio=-1
smokey-2499 [000] *.~3 61513.835131: cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=smokey next_pid=2504 next_prio=2
hi-thread-2504 [000] d.~3 61513.835132: cobalt_shadow_hardened: state=0x48040 info=0x0
hi-thread-2504 [000] d.~3 61513.835132: cobalt_root_sysexit: result=1
hi-thread-2504 [000] d.~3 61513.835133: cobalt_head_sysentry: syscall=thread_setname
hi-thread-2504 [000] d.~3 61513.835134: cobalt_pthread_setname: pth=00000000ba35a01d name=hi-thread
hi-thread-2504 [000] d.~3 61513.835135: cobalt_head_sysexit: result=0
hi-thread-2504 [000] d.~3 61513.835136: cobalt_head_sysentry: syscall=clock_nanosleep
hi-thread-2504 [000] d.~3 61513.835137: cobalt_clock_nanosleep: clock_id=0 flags=0x0() rqt=(0.001000000)
hi-thread-2504 [000] *.~3 61513.835138: cobalt_thread_suspend: pid=2504 mask=0x4 timeout=1000001 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] *.~3 61513.835138: cobalt_timer_start: timer=000000004d21df54(smokey) value=1000001 interval=0 mode=rel
hi-thread-2504 [000] *.~3 61513.835138: cobalt_schedule: status=0x10000000
hi-thread-2504 [000] *.~3 61513.835139: cobalt_trace_pid: pid=2504, prio=2
hi-thread-2504 [000] *.~3 61513.835139: cobalt_switch_context: prev_name=hi-thread prev_pid=2504 prev_prio=2 prev_state=0x48044 ==> next_name=ROOT/0 next_pid=0 next_prio=-1
smokey-2499 [000] *.~3 61513.835140: cobalt_trace_pid: pid=2499, prio=-1
smokey-2499 [000] ...1 61513.835141: sys_futex -> 0x0
smokey-2499 [000] ..~1 61513.835144: cobalt_head_sysentry: syscall=migrate
smokey-2499 [000] ...1 61513.835144: cobalt_root_sysentry: syscall=migrate
smokey-2499 [000] ...1 61513.835144: cobalt_shadow_gohard: state=0x480c0 info=0x0
smokey-2499 [000] d..3 61513.835145: sched_stat_wait: comm=gdb pid=2495 delay=23982 [ns]
smokey-2499 [000] d..3 61513.835146: sched_switch: prev_comm=smokey prev_pid=2499 prev_prio=98 prev_state=S ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] *..3 61513.835147: cobalt_thread_resume: name=smokey pid=2499 mask=0x80
gdb-2495 [000] *..3 61513.835147: cobalt_trace_pid: pid=2499, prio=1
gdb-2495 [000] *.~3 61513.835147: cobalt_schedule: status=0x10000000
gdb-2495 [000] *.~3 61513.835147: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] *.~3 61513.835148: cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=smokey next_pid=2499 next_prio=1
smokey-2499 [000] d.~3 61513.835148: cobalt_shadow_hardened: state=0x48040 info=0x0
smokey-2499 [000] d.~3 61513.835149: cobalt_root_sysexit: result=1
smokey-2499 [000] *.~3 61513.835219: irq_pipeline_entry: irq=4354
smokey-2499 [000] *.~3 61513.835219: irq_handler_entry: irq=4354 name=Out-of-band LAPIC timer interrupt
smokey-2499 [000] *.~3 61513.835220: cobalt_timer_expire: timer=00000000d13b8aa9
smokey-2499 [000] *.~3 61513.835220: cobalt_tick_shot: next tick at 61513.836136 (delay: 915 us)
smokey-2499 [000] *.~3 61513.835221: irq_handler_exit: irq=4354 ret=handled
smokey-2499 [000] *.~3 61513.835221: irq_pipeline_exit: irq=4354
smokey-2499 [000] *.~3 61513.836137: irq_pipeline_entry: irq=4354
smokey-2499 [000] *.~3 61513.836137: irq_handler_entry: irq=4354 name=Out-of-band LAPIC timer interrupt
smokey-2499 [000] *.~3 61513.836138: cobalt_timer_expire: timer=000000004d21df54
smokey-2499 [000] *.~3 61513.836138: cobalt_thread_resume: name=hi-thread pid=2504 mask=0x4
smokey-2499 [000] *.~3 61513.836138: cobalt_trace_pid: pid=2504, prio=2
smokey-2499 [000] *.~3 61513.836139: cobalt_timer_stop: timer=000000004d21df54
smokey-2499 [000] *.~3 61513.836139: irq_handler_exit: irq=4354 ret=handled
smokey-2499 [000] *.~3 61513.836139: irq_pipeline_exit: irq=4354
smokey-2499 [000] *.~3 61513.836140: cobalt_schedule: status=0x10000000
smokey-2499 [000] *.~3 61513.836140: cobalt_trace_pid: pid=2499, prio=1
smokey-2499 [000] *.~3 61513.836140: cobalt_switch_context: prev_name=smokey prev_pid=2499 prev_prio=1 prev_state=0x48048 ==> next_name=hi-thread next_pid=2504 next_prio=2
hi-thread-2504 [000] *.~3 61513.836141: cobalt_trace_pid: pid=2504, prio=2
hi-thread-2504 [000] d.~3 61513.836141: cobalt_head_sysexit: result=0
hi-thread-2504 [000] *.~3 61513.836142: cobalt_thread_fault: ip=0x55555540b580 type=0x3
hi-thread-2504 [000] *.~3 61513.836143: cobalt_thread_suspend: pid=2499 mask=0x400000 timeout=0 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] d.~3 61513.836143: cobalt_shadow_gorelax: reason=fault
hi-thread-2504 [000] d.~3 61513.836143: cobalt_lostage_request: request=wakeup pid=2504 comm=hi-thread
hi-thread-2504 [000] *.~3 61513.836144: cobalt_thread_suspend: pid=2504 mask=0x80 timeout=0 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] *.~3 61513.836144: cobalt_schedule: status=0x10000000
hi-thread-2504 [000] *.~3 61513.836144: cobalt_trace_pid: pid=2504, prio=2
hi-thread-2504 [000] *.~3 61513.836145: cobalt_switch_context: prev_name=hi-thread prev_pid=2504 prev_prio=2 prev_state=0x480c0 ==> next_name=ROOT/0 next_pid=0 next_prio=-1
gdb-2495 [000] *.~3 61513.836146: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] d.h3 61513.836146: irq_handler_entry: irq=120 name=in-band work
gdb-2495 [000] d.h3 61513.836147: cobalt_lostage_wakeup: pid=2504 comm=hi-thread
gdb-2495 [000] d.h5 61513.836147: sched_waking: comm=hi-thread pid=2504 prio=97 target_cpu=000
gdb-2495 [000] dNh6 61513.836147: sched_wakeup: comm=hi-thread pid=2504 prio=97 target_cpu=000
gdb-2495 [000] dNh3 61513.836148: irq_handler_exit: irq=120 ret=handled
gdb-2495 [000] dNh3 61513.836148: irq_handler_entry: irq=124 name=proxy tick
gdb-2495 [000] dNh3 61513.836151: softirq_raise: vec=1 [action=TIMER]
gdb-2495 [000] dNh3 61513.836152: softirq_raise: vec=9 [action=RCU]
gdb-2495 [000] dNh4 61513.836152: sched_stat_runtime: comm=gdb pid=2495 runtime=1007474 [ns] vruntime=300515161229 [ns]
gdb-2495 [000] *Nh3 61513.836154: cobalt_timer_start: timer=00000000d13b8aa9([host-timer/0]) value=2395843 interval=0 mode=rel
gdb-2495 [000] *Nh3 61513.836155: cobalt_tick_shot: next tick at 61513.838550 (delay: 2395 us)
gdb-2495 [000] dNh3 61513.836155: irq_handler_exit: irq=124 ret=handled
gdb-2495 [000] .Ns3 61513.836156: softirq_entry: vec=1 [action=TIMER]
gdb-2495 [000] .Ns3 61513.836157: softirq_exit: vec=1 [action=TIMER]
gdb-2495 [000] .Ns3 61513.836157: softirq_entry: vec=9 [action=RCU]
gdb-2495 [000] dNs6 61513.836158: sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=000
gdb-2495 [000] dNs7 61513.836159: sched_stat_runtime: comm=gdb pid=2495 runtime=6881 [ns] vruntime=300515168110 [ns]
gdb-2495 [000] dNs7 61513.836160: sched_stat_blocked: comm=rcu_sched pid=11 delay=4188739 [ns]
gdb-2495 [000] dNs7 61513.836161: sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=000
gdb-2495 [000] .Ns3 61513.836164: softirq_exit: vec=9 [action=RCU]
gdb-2495 [000] d..3 61513.836165: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=hi-thread next_pid=2504 next_prio=97
hi-thread-2504 [000] ...1 61513.836167: cobalt_shadow_relaxed: state=0x480c0 info=0x200
hi-thread-2504 [000] *..2 61513.836169: cobalt_thread_suspend: pid=2499 mask=0x400000 timeout=0 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] *..2 61513.836170: cobalt_thread_suspend: pid=2504 mask=0x400000 timeout=0 timeout_mode=0 wchan=0000000000000000
hi-thread-2504 [000] d..2 61513.836170: signal_generate: sig=5 errno=0 code=128 comm=hi-thread pid=2504 grp=0 res=0
hi-thread-2504 [000] d..3 61513.836173: signal_generate: sig=17 errno=0 code=4 comm=gdb pid=2495 grp=1 res=0
hi-thread-2504 [000] d..3 61513.836175: sched_stat_wait: comm=rcu_sched pid=11 delay=14490 [ns]
hi-thread-2504 [000] d..3 61513.836175: sched_switch: prev_comm=hi-thread prev_pid=2504 prev_prio=97 prev_state=t ==> next_comm=rcu_sched next_pid=11 next_prio=120
rcu_sched-11 [000] d..3 61513.836179: sched_stat_runtime: comm=rcu_sched pid=11 runtime=4960 [ns] vruntime=300512173070 [ns]
rcu_sched-11 [000] d..3 61513.836179: sched_stat_wait: comm=gdb pid=2495 delay=19450 [ns]
rcu_sched-11 [000] d..3 61513.836180: sched_switch: prev_comm=rcu_sched prev_pid=11 prev_prio=120 prev_state=I ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] ...1 61513.836187: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a7cb0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.836197: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.836198: sys_newfstat(fd: 12, statbuf: 7ffe8b2a7ae0)
gdb-2495 [000] ...1 61513.836199: sys_newfstat -> 0x0
gdb-2495 [000] ...1 61513.836200: sys_read(fd: 12, buf: 5585fe9960e0, count: 400)
gdb-2495 [000] ...1 61513.836214: sys_read -> 0x3f1
gdb-2495 [000] ...1 61513.836217: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.836217: sys_close -> 0x0
gdb-2495 [000] ...1 61513.836221: sys_rt_sigprocmask(how: 2, nset: 7ffe8b2a7e60, oset: 0, sigsetsize: 8)
gdb-2495 [000] ...1 61513.836222: sys_rt_sigprocmask -> 0x0
gdb-2495 [000] d..2 61513.836223: signal_deliver: sig=17 errno=0 code=4 sa_handler=5585fdc414d0 sa_flags=14000000
gdb-2495 [000] ...1 61513.836225: sys_read(fd: f, buf: 7ffe8b2a7667, count: 1)
gdb-2495 [000] ...1 61513.836226: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.836227: sys_write(fd: 10, buf: 5585fe0354b1, count: 1)
gdb-2495 [000] ...1 61513.836229: sys_write -> 0x1
gdb-2495 [000] ...1 61513.836229: sys_rt_sigreturn()
gdb-2495 [000] ...1 61513.836233: sys_read(fd: 9, buf: 7ffe8b2a82e7, count: 1)
gdb-2495 [000] ...1 61513.836234: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.836235: sys_write(fd: 1, buf: 5585fe7a5290, count: 27)
gdb-2495 [000] d..4 61513.836236: sched_waking: comm=smokey pid=2493 prio=120 target_cpu=000
gdb-2495 [000] d..5 61513.836237: sched_stat_runtime: comm=gdb pid=2495 runtime=58399 [ns] vruntime=300515226509 [ns]
gdb-2495 [000] d..5 61513.836238: sched_stat_sleep: comm=smokey pid=2493 delay=1717179 [ns]
gdb-2495 [000] dN.5 61513.836239: sched_wakeup: comm=smokey pid=2493 prio=120 target_cpu=000
gdb-2495 [000] .N.1 61513.836240: sys_write -> 0x27
gdb-2495 [000] dN.3 61513.836241: sched_stat_wait: comm=smokey pid=2493 delay=0 [ns]
gdb-2495 [000] d..3 61513.836241: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2493 next_prio=120
smokey-2493 [000] ...1 61513.836244: sys_read -> 0x1
smokey-2493 [000] ..~1 61513.836246: cobalt_head_sysentry: syscall=read
...
smokey-2493 [000] d..3 61513.836344: sched_stat_runtime: comm=smokey pid=2493 runtime=106636 [ns] vruntime=300512333145 [ns]
smokey-2493 [000] d..3 61513.836344: sched_stat_wait: comm=gdb pid=2495 delay=106636 [ns]
smokey-2493 [000] d..3 61513.836345: sched_switch: prev_comm=smokey prev_pid=2493 prev_prio=120 prev_state=S ==> next_comm=gdb next_pid=2495 next_prio=120
gdb-2495 [000] ...1 61513.836347: sys_poll(ufds: 5585fe898350, nfds: 4, timeout_msecs: 0)
gdb-2495 [000] ...1 61513.836348: sys_poll -> 0x1
gdb-2495 [000] ...1 61513.836350: sys_read(fd: f, buf: 7ffe8b2a7f27, count: 1)
gdb-2495 [000] ...1 61513.836351: sys_read -> 0x1
gdb-2495 [000] ...1 61513.836352: sys_read(fd: f, buf: 7ffe8b2a7f27, count: 1)
gdb-2495 [000] ...1 61513.836352: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.836353: sys_rt_sigprocmask(how: 0, nset: 5585fe2d4a60, oset: 7ffe8b2a7e60, sigsetsize: 8)
gdb-2495 [000] ...1 61513.836354: sys_rt_sigprocmask -> 0x0
gdb-2495 [000] ...1 61513.836355: sys_wait4(upid: ffffffff, stat_addr: 7ffe8b2a7db4, options: 40000001, ru: 0)
gdb-2495 [000] ...1 61513.836355: sched_process_wait: comm=gdb pid=0 prio=120
gdb-2495 [000] ...1 61513.836357: sys_wait4 -> 0x9c8
gdb-2495 [000] ...1 61513.836360: sys_ptrace(request: c, pid: 9c8, addr: 0, data: 7ffe8b2a6ef0)
gdb-2495 [000] d..3 61513.836361: sched_wait_task: comm=hi-thread pid=2504 prio=97
gdb-2495 [000] ...1 61513.836363: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.836367: sys_ptrace(request: 4202, pid: 9c8, addr: 0, data: 7ffe8b2a7cb0)
gdb-2495 [000] d..3 61513.836368: sched_wait_task: comm=hi-thread pid=2504 prio=97
gdb-2495 [000] ...1 61513.836369: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.836370: sys_ptrace(request: c, pid: 9c8, addr: 0, data: 7ffe8b2a6f10)
gdb-2495 [000] d..3 61513.836370: sched_wait_task: comm=hi-thread pid=2504 prio=97
gdb-2495 [000] ...1 61513.836371: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.836372: sys_ptrace(request: d, pid: 9c8, addr: 0, data: 7ffe8b2a6f10)
gdb-2495 [000] d..3 61513.836373: sched_wait_task: comm=hi-thread pid=2504 prio=97
gdb-2495 [000] ...1 61513.836374: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.836376: sys_wait4(upid: ffffffff, stat_addr: 7ffe8b2a7db4, options: 40000001, ru: 0)
gdb-2495 [000] ...1 61513.836376: sched_process_wait: comm=gdb pid=0 prio=120
gdb-2495 [000] ...1 61513.836377: sys_wait4 -> 0x0
gdb-2495 [000] ...1 61513.836379: sys_rt_sigprocmask(how: 2, nset: 7ffe8b2a7e60, oset: 0, sigsetsize: 8)
gdb-2495 [000] ...1 61513.836379: sys_rt_sigprocmask -> 0x0
gdb-2495 [000] ...1 61513.836382: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a7cd0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.836399: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.836400: sys_newfstat(fd: 12, statbuf: 7ffe8b2a7b50)
gdb-2495 [000] ...1 61513.836401: sys_newfstat -> 0x0
gdb-2495 [000] ...1 61513.836402: sys_read(fd: 12, buf: 5585fe9960e0, count: 400)
gdb-2495 [000] ...1 61513.836409: sys_read -> 0x140
gdb-2495 [000] ...1 61513.836410: sys_read(fd: 12, buf: 5585fea6ccc0, count: 400)
gdb-2495 [000] ...1 61513.836410: sys_read -> 0x0
gdb-2495 [000] ...1 61513.836415: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.836416: sys_close -> 0x0
gdb-2495 [000] ...1 61513.836419: sys_read(fd: f, buf: 7ffe8b2a7f17, count: 1)
gdb-2495 [000] ...1 61513.836420: sys_read -> 0xfffffffffffffff5
gdb-2495 [000] ...1 61513.836421: sys_write(fd: 10, buf: 5585fe0354b1, count: 1)
gdb-2495 [000] ...1 61513.836422: sys_write -> 0x1
gdb-2495 [000] ...1 61513.836425: sys_ptrace(request: 1, pid: 9c8, addr: 7ffff777f370, data: 7ffe8b2a7878)
gdb-2495 [000] d..3 61513.836426: sched_wait_task: comm=hi-thread pid=2504 prio=97
gdb-2495 [000] ...1 61513.836428: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.836430: sys_ptrace(request: 3, pid: 9c8, addr: a8, data: 7ffe8b2a7bd8)
gdb-2495 [000] d..3 61513.836430: sched_wait_task: comm=hi-thread pid=2504 prio=97
gdb-2495 [000] ...1 61513.836431: sys_ptrace -> 0x0
gdb-2495 [000] ...1 61513.836433: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a70e0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.836446: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.836446: sys_pread64(fd: 12, buf: 7ffe8b2a7430, count: 900, pos: 7ffff67c9700)
gdb-2495 [000] ...1 61513.836449: sys_pread64 -> 0x900
gdb-2495 [000] ...1 61513.836450: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.836450: sys_close -> 0x0
gdb-2495 [000] ...1 61513.836479: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a7ad0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.836488: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.836489: sys_newfstat(fd: 12, statbuf: 7ffe8b2a7950)
gdb-2495 [000] ...1 61513.836490: sys_newfstat -> 0x0
gdb-2495 [000] ...1 61513.836490: sys_read(fd: 12, buf: 5585fea6ccc0, count: 400)
gdb-2495 [000] ...1 61513.836498: sys_read -> 0x14d
gdb-2495 [000] ...1 61513.836499: sys_read(fd: 12, buf: 5585fe9960e0, count: 400)
gdb-2495 [000] ...1 61513.836499: sys_read -> 0x0
gdb-2495 [000] ...1 61513.836503: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.836504: sys_close -> 0x0
gdb-2495 [000] ...1 61513.836507: sys_openat(dfd: ffffff9c, filename: 7ffe8b2a7ad0, flags: 80000, mode: 0)
gdb-2495 [000] ...1 61513.836514: sys_openat -> 0x12
gdb-2495 [000] ...1 61513.836515: sys_newfstat(fd: 12, statbuf: 7ffe8b2a7950)
gdb-2495 [000] ...1 61513.836515: sys_newfstat -> 0x0
gdb-2495 [000] ...1 61513.836516: sys_read(fd: 12, buf: 5585fe9960e0, count: 400)
gdb-2495 [000] ...1 61513.836521: sys_read -> 0x13b
gdb-2495 [000] ...1 61513.836522: sys_read(fd: 12, buf: 5585fea6ccc0, count: 400)
gdb-2495 [000] ...1 61513.836522: sys_read -> 0x0
gdb-2495 [000] ...1 61513.836525: sys_close(fd: 12)
gdb-2495 [000] ...1 61513.836525: sys_close -> 0x0
gdb-2495 [000] ...1 61513.836529: sys_tkill(pid: 9c3, sig: 13)
gdb-2495 [000] *..3 61513.836532: cobalt_thread_resume: name=smokey pid=2499 mask=0x400000
gdb-2495 [000] *..3 61513.836532: cobalt_trace_pid: pid=2499, prio=1
gdb-2495 [000] *..3 61513.836533: cobalt_thread_unblock: pid=2499 state=0x48848 info=0x0
gdb-2495 [000] *.~3 61513.836586: cobalt_schedule: status=0x10000000
gdb-2495 [000] *.~3 61513.836586: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] *.~3 61513.836587: cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=smokey next_pid=2499 next_prio=1
smokey-2499 [000] *.~3 61513.836589: cobalt_trace_pid: pid=2499, prio=1
smokey-2499 [000] *.~3 61513.836589: cobalt_shadow_gorelax: reason=undefined
smokey-2499 [000] *.~3 61513.836589: cobalt_lostage_request: request=wakeup pid=2499 comm=smokey
smokey-2499 [000] *.~3 61513.836590: cobalt_thread_suspend: pid=2499 mask=0x400080 timeout=0 timeout_mode=0 wchan=0000000000000000
smokey-2499 [000] *.~3 61513.836590: cobalt_schedule: status=0x10000000
smokey-2499 [000] *.~3 61513.836590: cobalt_trace_pid: pid=2499, prio=1
smokey-2499 [000] *.~3 61513.836591: cobalt_switch_context: prev_name=smokey prev_pid=2499 prev_prio=1 prev_state=0x4488c0 ==> next_name=ROOT/0 next_pid=0 next_prio=-1
gdb-2495 [000] *.~3 61513.836592: cobalt_trace_pid: pid=2495, prio=-1
gdb-2495 [000] d..5 61513.836592: sched_waking: comm=smokey pid=2499 prio=98 target_cpu=000
gdb-2495 [000] dN.6 61513.836594: sched_wakeup: comm=smokey pid=2499 prio=98 target_cpu=000
gdb-2495 [000] dN.3 61513.836594: signal_generate: sig=19 errno=0 code=-6 comm=smokey pid=2499 grp=0 res=0
gdb-2495 [000] dNh3 61513.836595: irq_handler_entry: irq=120 name=in-band work
gdb-2495 [000] dNh3 61513.836596: cobalt_lostage_wakeup: pid=2499 comm=smokey
gdb-2495 [000] *N~4 61513.838552: irq_pipeline_entry: irq=4354
gdb-2495 [000] *N~4 61513.838553: irq_handler_entry: irq=4354 name=Out-of-band LAPIC timer interrupt
gdb-2495 [000] *N~4 61513.838554: cobalt_timer_expire: timer=00000000d13b8aa9
gdb-2495 [000] *N~4 61513.838555: irq_handler_exit: irq=4354 ret=handled
gdb-2495 [000] *N~4 61513.838555: irq_pipeline_exit: irq=4354
gdb-2495 [000] dNh8 61513.981277: sched_waking: comm=systemd-journal pid=163 prio=120 target_cpu=000
gdb-2495 [000] dNh9 61513.981278: sched_stat_runtime: comm=gdb pid=2495 runtime=144934239 [ns] vruntime=300660160748 [ns]
gdb-2495 [000] dNh9 61513.981280: sched_stat_sleep: comm=systemd-journal pid=163 delay=111416392895 [ns]
gdb-2495 [000] dNh9 61513.981280: sched_wakeup: comm=systemd-journal pid=163 prio=120 target_cpu=000
gdb-2495 [000] dNh3 61513.981281: irq_handler_exit: irq=120 ret=handled
gdb-2495 [000] dNh3 61513.981282: irq_handler_entry: irq=124 name=proxy tick
gdb-2495 [000] dNh3 61513.981285: softirq_raise: vec=1 [action=TIMER]
gdb-2495 [000] dNh3 61513.981285: softirq_raise: vec=9 [action=RCU]
gdb-2495 [000] dNh4 61513.981286: sched_stat_runtime: comm=gdb pid=2495 runtime=8375 [ns] vruntime=300660169123 [ns]
gdb-2495 [000] dNh5 61513.981288: sched_waking: comm=cobalt_printf pid=2494 prio=120 target_cpu=000
gdb-2495 [000] dNh6 61513.981289: sched_stat_runtime: comm=gdb pid=2495 runtime=2987 [ns] vruntime=300660172110 [ns]
gdb-2495 [000] dNh6 61513.981291: sched_stat_sleep: comm=cobalt_printf pid=2494 delay=238660319 [ns]
gdb-2495 [000] dNh6 61513.981291: sched_wakeup: comm=cobalt_printf pid=2494 prio=120 target_cpu=000
gdb-2495 [000] dNh5 61513.981292: sched_waking: comm=cobalt_printf pid=2503 prio=120 target_cpu=000
gdb-2495 [000] dNh6 61513.981292: sched_stat_runtime: comm=gdb pid=2495 runtime=3069 [ns] vruntime=300660175179 [ns]
gdb-2495 [000] dNh6 61513.981294: sched_stat_sleep: comm=cobalt_printf pid=2503 delay=146611442 [ns]
gdb-2495 [000] dNh6 61513.981294: sched_wakeup: comm=cobalt_printf pid=2503 prio=120 target_cpu=000
gdb-2495 [000] *Nh3 61513.981295: cobalt_timer_start: timer=00000000d13b8aa9([host-timer/0]) value=588476 interval=0 mode=rel
gdb-2495 [000] *Nh3 61513.981296: cobalt_tick_shot: next tick at 61513.981884 (delay: 588 us)
gdb-2495 [000] dNh3 61513.981296: irq_handler_exit: irq=124 ret=handled
gdb-2495 [000] .Ns3 61513.981297: softirq_entry: vec=1 [action=TIMER]
gdb-2495 [000] dNs5 61513.981298: sched_waking: comm=rcu_sched pid=11 prio=120 target_cpu=000
gdb-2495 [000] dNs6 61513.981298: sched_stat_runtime: comm=gdb pid=2495 runtime=6218 [ns] vruntime=300660181397 [ns]
gdb-2495 [000] dNs6 61513.981299: sched_stat_blocked: comm=rcu_sched pid=11 delay=145119923 [ns]
gdb-2495 [000] dNs6 61513.981299: sched_wakeup: comm=rcu_sched pid=11 prio=120 target_cpu=000
gdb-2495 [000] dNs7 61513.981302: sched_waking: comm=kworker/0:1 pid=1932 prio=120 target_cpu=000
gdb-2495 [000] dNs8 61513.981302: sched_stat_runtime: comm=gdb pid=2495 runtime=3884 [ns] vruntime=300660185281 [ns]
gdb-2495 [000] dNs8 61513.981303: sched_stat_blocked: comm=kworker/0:1 pid=1932 delay=206048652 [ns]
gdb-2495 [000] dNs8 61513.981304: sched_wakeup: comm=kworker/0:1 pid=1932 prio=120 target_cpu=000
gdb-2495 [000] dNs5 61513.981309: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981309: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981310: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981310: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981310: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981311: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981311: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] dNs5 61513.981312: softirq_raise: vec=2 [action=NET_TX]
gdb-2495 [000] .Ns3 61513.981314: softirq_exit: vec=1 [action=TIMER]
gdb-2495 [000] .Ns3 61513.981314: softirq_entry: vec=9 [action=RCU]
gdb-2495 [000] .Ns3 61513.981315: softirq_exit: vec=9 [action=RCU]
gdb-2495 [000] dNs5 61513.981316: sched_waking: comm=ksoftirqd/0 pid=10 prio=120 target_cpu=000
gdb-2495 [000] dNs6 61513.981316: sched_stat_runtime: comm=gdb pid=2495 runtime=13841 [ns] vruntime=300660199122 [ns]
gdb-2495 [000] dNs6 61513.981317: sched_stat_sleep: comm=ksoftirqd/0 pid=10 delay=149349034 [ns]
gdb-2495 [000] dNs6 61513.981317: sched_wakeup: comm=ksoftirqd/0 pid=10 prio=120 target_cpu=000
gdb-2495 [000] .N.1 61513.981318: sys_tkill -> 0x0
gdb-2495 [000] d..3 61513.981320: sched_switch: prev_comm=gdb prev_pid=2495 prev_prio=120 prev_state=R ==> next_comm=smokey next_pid=2499 next_prio=98
smokey-2499 [000] *.~3 61513.981888: irq_pipeline_entry: irq=4354
smokey-2499 [000] *.~3 61513.981888: irq_handler_entry: irq=4354 name=Out-of-band LAPIC timer interrupt
smokey-2499 [000] *.~3 61513.981889: cobalt_timer_expire: timer=00000000d13b8aa9
smokey-2499 [000] *.~3 61513.981889: irq_handler_exit: irq=4354 ret=handled
smokey-2499 [000] *.~3 61513.981890: irq_pipeline_exit: irq=4354
smokey-2499 [000] d.h1 61514.106435: irq_handler_entry: irq=124 name=proxy tick
smokey-2499 [000] *.h1 61514.106441: cobalt_timer_start: timer=00000000d13b8aa9([host-timer/0]) value=2109534 interval=0 mode=rel
smokey-2499 [000] *.h1 61514.106441: cobalt_tick_shot: next tick at 61514.108550 (delay: 2109 us)
smokey-2499 [000] d.h1 61514.106442: irq_handler_exit: irq=124 ret=handled
smokey-2499 [000] ...1 61514.106442: cobalt_shadow_relaxed: state=0x4488c0 info=0x200
smokey-2499 [000] *.~1 61514.108552: irq_pipeline_entry: irq=4354
next prev parent reply other threads:[~2021-04-30 8:07 UTC|newest]
Thread overview: 16+ messages / expand[flat|nested] mbox.gz Atom feed top
2021-04-28 3:19 gdb test failure debug status update Chen, Hongzhan
2021-04-28 14:18 ` Philippe Gerum
2021-04-28 14:30 ` Philippe Gerum
2021-04-29 6:31 ` Chen, Hongzhan
2021-04-30 5:25 ` Chen, Hongzhan
2021-04-30 5:51 ` Chen, Hongzhan
2021-04-30 7:36 ` Philippe Gerum
2021-04-30 7:34 ` Philippe Gerum
2021-04-30 8:00 ` Philippe Gerum
2021-04-30 8:07 ` Chen, Hongzhan [this message]
[not found] ` <DM5PR11MB18529649C47BF241930A2217F25E9@DM5PR11MB1852.namprd11.prod.outlook.com>
[not found] ` <8735v82jmd.fsf@xenomai.org>
2021-05-06 2:00 ` Chen, Hongzhan
2021-05-07 1:10 ` Chen, Hongzhan
2021-05-09 17:46 ` Philippe Gerum
2021-05-09 17:49 ` Philippe Gerum
2021-05-10 2:16 ` Chen, Hongzhan
2021-05-15 15:55 ` Philippe Gerum
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=DM5PR11MB18527EA509FB99BF50D1ACFFF25E9@DM5PR11MB1852.namprd11.prod.outlook.com \
--to=hongzhan.chen@intel.com \
--cc=rpm@xenomai.org \
--cc=xenomai@xenomai.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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.