<div dir="ltr">Hi,<div><br></div><div>Was curious if any of the experts had any comments/suggestions on the issue I am facing.</div><div><br></div><div>Thanks</div><div>Anup</div><div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Dec 27, 2017 at 9:02 PM, Anup Pemmaiah <span dir="ltr"><<a href="mailto:anup.pemmaiah@gmail.com" target="_blank">anup.pemmaiah@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><br><div class="gmail_extra"><br><div class="gmail_quote"><span>On Wed, Dec 27, 2017 at 6:40 PM, Jonathan Rajotte-Julien <span dir="ltr"><<a href="mailto:jonathan.rajotte-julien@efficios.com" target="_blank">jonathan.rajotte-julien@effic<wbr>ios.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hi,<br>
<span class="m_8854001346163611844m_-4183753690866262461gmail-"><br>
On Wed, Dec 27, 2017 at 05:21:30PM -0800, Anup Pemmaiah wrote:<br>
> Hi,<br>
><br>
> I am trying to find the reason of a intermittent latency that I am noticing<br>
> on my Linux system running on a RT_PREEMPT kernel. I have patched it on a<br>
> Ubuntu 16.04 LTS. Have stopped the desktop lightdm service and this is on a<br>
<br>
</span>Could we get more details on the version of the RT kernel? Version/patchset?<br></blockquote><div><br></div></span><div>The kernel and RT_PREEMPT patch is 4.4.38-rt49</div><span><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<span class="m_8854001346163611844m_-4183753690866262461gmail-"><br>
> Arm aarch64 platform.<br>
><br>
> At a very high level, there are two processes interacting with each other.<br>
> Process-1 does some work and sends UDP messages to Process-2 (Using the<br>
> FASTRTPS real time Publish-Subscribe protocol).<br>
<br>
</span>Are you using the eProsima implementation? If so, could you give us more<br>
information on the tracing strategy?<br></blockquote><div><br></div><div><br></div><div> </div></span><div>Yes. In my situation, it is part of the ROS(<a href="http://www.ros.org/" target="_blank">http://www.ros.org/</a>) stack. So ROS middlewear uses eProsima underneath for publishing and subscribing. My process sits on top of ROS stack and</div><div>uses it for message passing.</div><div><br></div><div><br></div><div>Right now I have not addigned at RT priorities. All tasks are running with SCHED_OTHER with default prio 20.<br></div><div><br></div><div>I load the modules as follows</div><div><br></div><div>$modprobe latency_tracker</div><div><br></div><div>$modprobe latency_tracker_syscalls<br></div><div><br></div><div>$modprobe lttng-probe-latency_tracker</div><div><br></div><div>$echo 100000 > /sys/kernel/debug/latency/sysc<wbr>alls/default/threshold</div><div><br></div><div>Start LTTng</div><div><br></div><div>$sudo lttng-sessiond --daemonize</div><div><br></div><div>$echo 1 > /sys/kernel/debug/latency/sysc<wbr>alls/default/tracking_on</div><div><br></div><div><br></div><div>Process-1 has a thread which keeps doing some work and publishing messages every 100ms. I start Process-1 as</div><div><br></div><div>LD_PRELOAD=liblttng-profile.so <Process-1><br></div><div><br></div><div>It gives some relevant information about few stack traces. </div><div><div><br></div><div>Timestamp<span style="white-space:pre-wrap"> </span>Channel<span style="white-space:pre-wrap"> </span>CPU<span style="white-space:pre-wrap"> </span>Event type<span style="white-space:pre-wrap"> </span>Contents<span style="white-space:pre-wrap"> </span>Binary Location<span style="white-space:pre-wrap"> </span>Function Location<span style="white-space:pre-wrap"> </span>Source Location<span style="white-space:pre-wrap"> </span>TID</div><div>16:13:32.971 988 199<span style="white-space:pre-wrap"> </span>u_5<span style="white-space:pre-wrap"> </span>5<span style="white-space:pre-wrap"> </span>lttng_profile:off_cpu_sample<span style="white-space:pre-wrap"> </span>stack=/lib/aarch64-linux-gnu/l<wbr>ibpthread.so.0(__nanosleep+0x2<wbr>8) [0x7f98233238]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_Z<wbr>NK8velodyne14input_socket_c11r<wbr>ead_packetERNS_8packet_sE+0x16<wbr>0) [0x7f9826e418]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_<wbr>ZN8velodyne8driver_c16read_<wbr>from_socketEv+0x30) [0x7f9826c390]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_Z<wbr>NK8velodyne8driver_c3runESt8fu<wbr>, overhead=313869, context._vtid=11713<span style="white-space:pre-wrap"> </span>11713</div><div><br></div><div>16:13:32.973 972 119<span style="white-space:pre-wrap"> </span>u_0<span style="white-space:pre-wrap"> </span>0<span style="white-space:pre-wrap"> </span>lttng_profile:off_cpu_sample<span style="white-space:pre-wrap"> </span>stack=/lib/aarch64-linux-gnu/l<wbr>ibpthread.so.0(__nanosleep+0x2<wbr>8) [0x7f98233238]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_Z<wbr>NK8velodyne14input_socket_c11r<wbr>ead_packetERNS_8packet_sE+0x16<wbr>0) [0x7f9826e418]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_<wbr>ZN8velodyne8driver_c16read_<wbr>from_socketEv+0x30) [0x7f9826c390]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_Z<wbr>NK8velodyne8driver_c3runESt8fu<wbr>, overhead=809697, context._vtid=11713<span style="white-space:pre-wrap"> </span>11713</div><div><br></div><div>16:13:32.973 981 912<span style="white-space:pre-wrap"> </span>u_4<span style="white-space:pre-wrap"> </span>4<span style="white-space:pre-wrap"> </span>lttng_profile:off_cpu_sample<span style="white-space:pre-wrap"> </span>stack=/lib/aarch64-linux-gnu/l<wbr>ibpthread.so.0(__nanosleep+0x2<wbr>8) [0x7f98233238]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_Z<wbr>NK8velodyne8driver_c3runESt8fu<wbr>nctionIFvvEE+0x94) [0x7f9826c4a4]</div><div>/home/nvidia/workspace/test_67<wbr>2/grand_central/apex_ws/instal<wbr>l/lib/libvelodyne_driver.so(_<wbr>ZNSt6thread5_ImplISt12_Bind_<wbr>simpleIFSt7_Mem_<wbr>fnIMN8velodyne8driver_cEKFvSt8<wbr>functionIFvvEEEEPS4_St5_<wbr>BindIFS2_IMS4_FvvEESB_EEEEE6_<wbr>M_runEv+0x8c) [0x7f9826d9fc]</div><div>/usr/lib/aarch64-linux-gnu/lib<wbr>stdc++.so., overhead=469267, context._vtid=11715<span style="white-space:pre-wrap"> </span>11715</div><div><br></div><div>16:13:32.973 999 544<span style="white-space:pre-wrap"> </span>u_3<span style="white-space:pre-wrap"> </span>3<span style="white-space:pre-wrap"> </span>lttng_profile:off_cpu_sample<span style="white-space:pre-wrap"> </span>stack=/lib/aarch64-linux-gnu/l<wbr>ibpthread.so.0(sendmsg+0x2c) [0x7f9823303c]</div><div>/opt/ros2/lib/libfastrtps.so.1<wbr>(_ZN8eprosima8fastrtps4rtps14U<wbr>DPv4Transport17SendThroughSock<wbr>etEPKhjRKNS1_9Locator_tERN4asi<wbr>o21basic_datagram_socketINS8_<wbr>2ip3udpEEE+0xf8) [0x7f9647ad88]</div><div>/opt/ros2/lib/libfastrtps.so.1<wbr>(_ZN8eprosima8fastrtps4rtps14U<wbr>DPv4Transport4SendEPKhjRKNS1_9<wbr>Locator_tES7_+0x158) [0x7f9647c3e0]</div><div>/opt/ros2/lib/libfastrtps.so.1<wbr>(_ZN8eprosima8fastrtps4rtps14S<wbr>enderResource4SendEPKhjRKNS1_9<wbr>Locator_tE+0x4c) [0x7f9644b58c]</div><div>/opt/ros2/lib/, overhead=1289108, context._vtid=11712<span style="white-space:pre-wrap"> </span>11712</div></div><div><br></div><div>Once in a while when I kill the process with <ctrl-c> it hangs but not always.</div><div><br></div><div>Process-2 has a thread which subscribes for the messages.</div><div><br></div><div>When I start LD_PRELOAD=liblttng-profile.so <Process-2>, it just hangs<br></div><span><div><br></div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<span class="m_8854001346163611844m_-4183753690866262461gmail-"><br>
> Data is sent from Process-1 to Process-2 every 100ms. I see that often<br>
> there is a delay in Process-2 receiving the message.<br>
><br>
><br>
> Trying to use LTTng and along with other supported profiling tools like<br>
> latency-tracker, lttng-profile.<br>
> Something like the description in this link<br>
> <a href="http://lttng.org/blog/2015/03/18/full-stack-latencies" rel="noreferrer" target="_blank">http://lttng.org/blog/2015/03/<wbr>18/full-stack-latencies</a> is what I am looking<br>
> for, but I am facing issues. The latency_tracker kernel modules and also<br>
> lttng-profile is a bit flaky as it sometimes work and sometimes panics the<br>
> kernel. Simple test cases as provided in<br>
> <a href="https://github.com/fdoray/latency_tracker_demo" rel="noreferrer" target="_blank">https://github.com/fdoray/late<wbr>ncy_tracker_demo</a> works sometimes. And also<br>
<br>
</span>Not sure if those aged properly.<br>
<br>
If you did not already, I would recommend you take a look at the latency-tracker<br>
github page [1] that this project references and uses. It changed quite a lot<br>
in the last 3 years.<br>
<br>
[1] <a href="https://github.com/efficios/latency-tracker" rel="noreferrer" target="_blank">https://github.com/efficios/la<wbr>tency-tracker</a></blockquote><div><br></div></span><div>Yes, that is where I downloaded the source and followed. </div><span><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><br>
<span class="m_8854001346163611844m_-4183753690866262461gmail-"><br>
<br>
> profiling Process-1 works by providing some useful traces(intermittently<br>
> kernel panics), but profiling Process-2 the process just hangs.<br>
<br>
</span>What version of lttng-modules are you using? The latency_tracker_demo install<br>
script seems to use lttng-modules 2.6. 2.6 is not supported anymore, it would be<br>
interesting to perform you experimentation with a newer version.<br></blockquote><div><br></div></span><div>Sorry for not being clear in my earlier msg. I did not use the install scripts. All the kernel mdoules, LTTng modules, latency-tracker modules and user space libs </div><div>lttng-ust, lttng-tools, lttng-profile was downloaded from git hub few weeks ago and build from source and loaded. </div><div><br></div><div>From the latency_tracker_demo, I just built the sleep-demo and used the trace.sh to do the tracing</div><span><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<br>
Still, could you provide the panics call stack?<br></blockquote><div><br></div></span><div>I do not see a panic trace all the time. In the previous run, when I tried to kill the Process-2 with "kill -9 <pid>", as it was hung, the system just rebooted without panic.</div><div><br></div><div><br></div><div>This is from the syslog, and I see the same output on console</div><div><br></div><div><div>1613 Dec 27 16:53:37 kernel: [12566.627939] ring buffer relay-metadata: 0 records written, 0 records overrun</div><div>1614 Dec 27 16:53:37 kernel: [12566.634983] ring buffer relay-metadata, cpu -1: non-consumed data</div><div>1615 Dec 27 16:53:37 kernel: [12566.634983] [ 12288 bytes written, 8192 bytes read ]</div><div>1616 Dec 27 16:53:37 kernel: [12566.646189] ring buffer: relay-metadata, cpu -1: 8192 bytes committed</div><div>1617 Dec 27 16:53:37 kernel: [12566.652780] ring buffer relay-discard, cpu 0: 0 records written, 0 records overrun</div><div>1618 Dec 27 16:53:38 kernel: [12566.660865] ring buffer relay-discard, cpu 1: 0 records written, 0 records overrun</div><div>1619 Dec 27 16:53:38 kernel: [12566.668924] ring buffer relay-discard, cpu 2: 0 records written, 0 records overrun</div><div>1620 Dec 27 16:53:38 kernel: [12566.676897] ring buffer relay-discard, cpu 3: 0 records written, 0 records overrun</div><div>1621 Dec 27 16:53:38 kernel: [12566.684809] ring buffer relay-discard, cpu 4: 0 records written, 0 records overrun</div><div>1622 Dec 27 16:53:38 kernel: [12566.692681] ring buffer relay-discard, cpu 5: 0 records written, 0 records overrun</div><div>1623 Dec 27 16:54:16 avahi-daemon[948]: Registering new address record for 10.31.33.48 on eth0.IPv4.</div><div>1624 Dec 27 16:54:16 rsyslogd-2007: action 'action 9' suspended, next retry is Wed Dec 27 16:55:46 2017 [v8.16.0 t ry <a href="http://www.rsyslog.com/e/2007" target="_blank">http://www.rsyslog.com/e/2007</a> ]</div><div>1625 Dec 27 16:54:16 systemd-timesyncd[816]: Network configuration changed, trying to establish connection.</div><div>1626 Dec 27 16:54:16 systemd-timesyncd[816]: Synchronized to time server <a href="http://91.189.94.4:123" target="_blank">91.189.94.4:123</a> (<a href="http://ntp.ubuntu.com" target="_blank">ntp.ubuntu.com</a>).</div><div>1627 Dec 27 16:54:17 rsyslogd: [origin software="rsyslogd" swVersion="8.16.0" x-pid="924" x-info="<a href="http://www.rsysl" target="_blank">http://www.rsysl</a> <a href="http://og.com" target="_blank">og.com</a>"] start </div><div>1628 Dec 27 16:54:17 rsyslogd-2222: command 'KLogPermitNonKernelFacility' is currently not permitted - did you alr eady set it via a RainerScript command (v6+ config)? [v8.16.0 try <a href="http://www.rsyslog.com/e/2222" target="_blank">http://www.rsyslog.com/e/2222</a> ]</div><div>1629 Dec 27 16:54:17 rsyslogd: rsyslogd's groupid changed to 115</div><div>1630 Dec 27 16:54:17 rsyslogd: rsyslogd's userid changed to 108</div><div>1631 Dec 27 16:54:17 kernel: [ 0.000000] Booting Linux on physical CPU 0x100 </div><div>1632 Dec 27 16:54:17 kernel: [ 0.000000] Initializing cgroup subsys cpuset</div><div>1633 Dec 27 16:54:17 kernel: [ 0.000000] Initializing cgroup subsys cpu</div><div>1634 Dec 27 16:54:17 kernel: [ 0.000000] Initializing cgroup subsys cpuacct</div><div>1635 Dec 27 16:54:17 kernel: [ 0.000000] Linux version 4.4.38-rt49-tegra (anup.pemmaiah@anup-pemmaiah) (gcc ver sion 4.9.2 (GCC) ) #1 SMP PREEMPT RT Thu Nov 30 17:12:21 PST 2017</div><div>1636 Dec 27 16:54:17 kernel: [ 0.000000] Boot CPU: AArch64 Processor [411fd073]</div><div>1637 Dec 27 16:54:17 kernel: [ 0.000000] earlycon: Early serial console at MMIO32</div></div><span><div> <br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<span class="m_8854001346163611844m_-4183753690866262461gmail-"><br>
><br>
> Not sure how updated the above pasted links are, because I notice there is<br>
> no more usec_threshold parameter and I use the threshold<br>
> in /sys/kernel/debug/latency/sysc<wbr>alls/default/threshold<br>
><br>
> I understand each situation is different, but was curious if any of you<br>
> have comments/suggestions that would help in debugging latency related<br>
> issues using LTTng. I have looked many places to get required info but of<br>
> not much help.<br>
<br>
</span>Most of the maintainers are on vacation during this part of the year so it might<br>
take some time to get answers. I'm sure that Julien Desfossez will be<br>
interested in your use case.<br>
<br>
Cheers<br></blockquote><div><br></div></span><div>I undersatnd and any suggestions will be very helpful </div><span><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<span class="m_8854001346163611844m_-4183753690866262461gmail-"><br>
><br>
> Your comments/suggestions will be greatly appreciated.<br>
><br>
> Thanks<br>
> Anup<br>
<br>
</span>> ______________________________<wbr>_________________<br>
> lttng-dev mailing list<br>
> <a href="mailto:lttng-dev@lists.lttng.org" target="_blank">lttng-dev@lists.lttng.org</a><br>
> <a href="https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev" rel="noreferrer" target="_blank">https://lists.lttng.org/cgi-bi<wbr>n/mailman/listinfo/lttng-dev</a><br>
<span class="m_8854001346163611844m_-4183753690866262461gmail-HOEnZb"><font color="#888888"><br>
<br>
--<br>
Jonathan Rajotte-Julien<br>
EfficiOS<br>
</font></span></blockquote></span></div><br></div></div>
</blockquote></div><br></div></div></div>