On 10.05.2013 14:42, Stanislav Meduna wrote:
> I have uploaded the trace.dat captured by
> trace-cmd start -b 64000 -e irq -e sched -e syscalls -e timer
Actually the problem probably comes earlier. The thread with id 1276
normally tries to call setsockopt and then right after it
returns a select is called. See e.g. trace #914414 @ 49720.850080.
There is no way in the code it can wait for more than tens of
microseconds - no loop, no lock, just two function calls.
With -p function -n '*preempt_count' (which unfortunately changes
the timings so that the problem does not occur) there is nothing
logged between the calls as well, except the syscall_trace_entry
function.
However, at #1800630 @ 49762.927207 the setsockopt returns,
but the expected system call is not entered for 600 us
and no irq, sched or timer event is logged in between.
I also have another instance of the crash where the timing
is different - the thread runs for 4 ms with soft and hard
interrupts coming, so I am sure that this is not some SMI.
It really looks that something is spinning here.
At #1800649 the priority of the thread is boosted, i.e. there
most probably _is_ a PI lock held. It even looks to be unlocked
at #1800658 where the priority boost goes away.
Which one? What locking happens between sys_exit_socketcall
is logged and the time next syscall entry is logged?
The problem akso happens with the whole CONFIG_FTRACE subtree
disabled, so if there is some lock only present if the
tracers are present, it is not the (only) culprit.
Thanks
--
Stano
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
