Re: [Socketcan-users] Message stalls in SocketCan Layer?

[Wolfgang Grandegger <wg@grandegger.com>]

Hi Michael,

On 02/13/2012 11:00 AM, Michael Jäntsch wrote:
> Hi,
> 
> sorry for the late reply. I wanted to test the older kernel and
> therefore needed to setup the OS from scratch which I didn't have time
> to do right away. Now, I tested it with Ubuntu 11.04 and kernel 2.6.38-13.
> The problem appears a lot less often. From the time frame of a few
> minutes we went to something more like half an hour. So maybe this has
> been there all along but did not appear frequently enough to be noticed.
> For the reasons I already mentioned I'm still pretty sure this has
> nothing to do with our code.
> Does anybody have an idea how to go about debugging this?
> 
> On 03.02.2012 20:41, Wolfgang Grandegger wrote:
>> On 02/03/2012 05:57 PM, Oliver Hartkopp wrote:
>>> please consider that if it works on other machines with the same kernel that
>>> there could be some changes within the USB subsystem or some interrupt or
>>> ACPI/powersaving issues too.
>>>
>>> Going back to an older Kernel is a good check - don't know, if you also can go
>>> further (3.1, 3.2) with Ubuntu 11.10 too ?!?
>>>
>>> Maybe there's some USB debugging available to check whether the URB has been
>>> sent properly to the USB wire and if the interrupt of the USB controller
>>> reached the system after sending.
>> IIUC, he said that the time stamps indicated that the USB transfers have
>> happened in time. The delays occured later. That's wired, indeed.
> Wolfgang is right, the debug output of the driver indicated that the USB
> transfers happened in time which is why I the guys from PEAK send me to
> you. This looks to me like the messages get stalled somewhere in the
> PF_CAN netlayer, but I'm also not a hundred percent sure how to verify
> this, as this of course not that reproducable. Any ideas?

Ftrace may help to find the problem. It's not too difficult to use, I
think. I assume that function tracing is enabled in your kernel. You
should find in your ".config":

CONFIG_DEBUG_FS=y
CONFIG_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_DYNAMIC_FTRACE=y

With that kernel, activate FTRACE as shown below:

Mount DebugFS file system
# mount -t debugfs nope /sys/kernel/debug
Stop tracing
# echo 0 > /sys/kernel/debug/tracing/tracing_on
Clear trace buffer
# echo 0 > /sys/kernel/debug/tracing/trace
If necessary, increase buffer size
# echo 16384 > /sys/kernel/debug/tracing/buffer_size_kb
Use function tracer
# cat /sys/kernel/debug/tracing/available_tracers
... function ...
# echo function > /sys/kernel/debug/tracing/current_tracer
Finally enable ftracing
# echo 1 > /sys/kernel/debug/tracing/tracing_on
Inspect trace buffer
# cat /sys/kernel/debug/tracing/trace

This will create a huge amount of data. In a first step, only the
functions relevant for CAN might be enabled to debug the timing.

When you realize the long delay in your application, you should call
"echo 0 > /sys/kernel/debug/tracing/tracing_on" from the application
context (using fopen, etc.) to freeze the trace. That should give you
more or less detailed information on what has happened. I think it's not
too complicated. Interpreting the traces might be harder, tough.

Some useful links are:

http://lxr.linux.no/#linux+v2.6.37/Documentation/trace/ftrace.txt

There are also a few nice articles about Ftrace at LWN.

Wolfgang.