CINXE.COM
LKML: "kus Kusche Klaus": RE: Latency traces I cannot interpret (sa1100, 2.6.15-rc7-rt1)
<?xml version="1.0" encoding="UTF-8" standalone="yes"?> <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"><html xmlns="http://www.w3.org/1999/xhtml"><head><meta http-equiv="Content-Type" content="text/html; charset=UTF-8" /><title>LKML: "kus Kusche Klaus": RE: Latency traces I cannot interpret (sa1100, 2.6.15-rc7-rt1)</title><link href="/css/message.css" rel="stylesheet" type="text/css" /><link href="/css/wrap.css" rel="alternate stylesheet" type="text/css" title="wrap" /><link href="/css/nowrap.css" rel="stylesheet" type="text/css" title="nowrap" /><link href="/favicon.ico" rel="shortcut icon" /><script src="/js/simple-calendar.js" type="text/javascript"></script><script src="/js/styleswitcher.js" type="text/javascript"></script><link rel="alternate" type="application/rss+xml" title="lkml.org : last 100 messages" href="/rss.php" /><link rel="alternate" type="application/rss+xml" title="lkml.org : last messages by "kus Kusche Klaus"" href="/groupie.php?aid=28594" /><!--Matomo--><script> var _paq = window._paq = window._paq || []; /* tracker methods like "setCustomDimension" should be called before "trackPageView" */ _paq.push(["setDoNotTrack", true]); _paq.push(["disableCookies"]); _paq.push(['trackPageView']); _paq.push(['enableLinkTracking']); (function() { var u="//m.lkml.org/"; _paq.push(['setTrackerUrl', u+'matomo.php']); _paq.push(['setSiteId', '1']); var d=document, g=d.createElement('script'), s=d.getElementsByTagName('script')[0]; g.async=true; g.src=u+'matomo.js'; s.parentNode.insertBefore(g,s); })(); </script><!--End Matomo Code--></head><body onload="es.jasper.simpleCalendar.init();" itemscope="itemscope" itemtype="http://schema.org/BlogPosting"><table border="0" cellpadding="0" cellspacing="0"><tr><td width="180" align="center"><a href="/"><img style="border:0;width:135px;height:32px" src="/images/toprowlk.gif" alt="lkml.org" /></a></td><td width="32">聽</td><td class="nb"><div><a class="nb" href="/lkml"> [lkml]</a> 聽 <a class="nb" href="/lkml/2005"> [2005]</a> 聽 <a class="nb" href="/lkml/2005/12"> [Dec]</a> 聽 <a class="nb" href="/lkml/2005/12/30"> [30]</a> 聽 <a class="nb" href="/lkml/last100"> [last100]</a> 聽 <a href="/rss.php"><img src="/images/rss-or.gif" border="0" alt="RSS Feed" /></a></div><div>Views: <a href="#" class="nowrap" onclick="setActiveStyleSheet('wrap');return false;">[wrap]</a><a href="#" class="wrap" onclick="setActiveStyleSheet('nowrap');return false;">[no wrap]</a> 聽 <a class="nb" href="/lkml/mheaders/2005/12/30/59" onclick="this.href='/lkml/headers'+'/2005/12/30/59';">[headers]</a>聽 <a href="/lkml/bounce/2005/12/30/59">[forward]</a>聽 </div></td><td width="32">聽</td></tr><tr><td valign="top"><div class="es-jasper-simpleCalendar" baseurl="/lkml/"></div><div class="threadlist">Messages in this thread</div><ul class="threadlist"><li class="root"><a href="/lkml/2005/12/30/59">First message in thread</a></li><li class="origin"><a href="/lkml/2005/12/30/67">"kus Kusche Klaus"</a><ul><li><a href="/lkml/2005/12/30/67">Daniel Walker</a></li></ul></li></ul></td><td width="32" rowspan="2" class="c" valign="top"><img src="/images/icornerl.gif" width="32" height="32" alt="/" /></td><td class="c" rowspan="2" valign="top" style="padding-top: 1em"><table><tr><td><table><tr><td class="lp">Subject</td><td class="rp" itemprop="name">RE: Latency traces I cannot interpret (sa1100, 2.6.15-rc7-rt1)</td></tr><tr><td class="lp">Date</td><td class="rp" itemprop="datePublished">Fri, 30 Dec 2005 13:40:20 +0100</td></tr><tr><td class="lp">From</td><td class="rp" itemprop="author">"kus Kusche Klaus" <></td></tr></table></td><td></td></tr></table><pre itemprop="articleBody">> From: Ingo Molnar<br />> there seem to be leaked preempt counts:<br />> <br />> <idle>-0 0.n.1 8974us : touch_critical_timing (cpu_idle)<br />> <br />> we should never have preemption disabled in cpu_idle(). To <br />> debug leaked <br />> preemption counts, enable CONFIG_DEBUG_PREEMPT.<br /><br />Something really fishy is going on here: <br />That 9 ms latency seems to be really *idle* time!<br /><br />* If the box is idle, I get that trace almost immediately, and<br />almost always with close to 9 ms (system clock is 100 Hz, <br />i.e. 10 ms tick period).<br /><br />* If the box is 100 % loaded, I don't get that trace. I get<br />different traces from different processes, mostly shorter than<br />9 ms.<br /><br />* If I load the box with work at regular intervals <br />and idle time in between, I get traces<br />identical to the 9 ms idle trace, but consistently shorter.<br />If I throw a flood ping with 1000 pkt/s against my box, the idle<br />trace shows up with 800 or 900 microseconds, i.e. the idle time<br />between packets.<br /><br />Now, is the tracer wrong, or has the idle time a wrong status?<br /><br />By the way, I had one trace today where the cat /proc/latency_trace<br />itself showed up:<br /><br /> \ / ||||| \ | / <br /> cat-3129 0D... 1us!: preempt_schedule_irq (svc_preempt)<br /> cat-3129 0.... 5502us+: rt_up (l_start)<br /> cat-3129 0D..1 5511us+: check_raw_flags (rt_up)<br /> cat-3129 0...1 5514us+: rt_up (l_start)<br /> cat-3129 0...1 5518us : sub_preempt_count_ti (rt_up)<br /><br />What's happening in those 5 ms?<br /><br />-- <br />Klaus Kusche (Software Development - Control Systems)<br />KEBA AG Gewerbepark Urfahr, A-4041 Linz, Austria (Europe)<br />Tel: +43 / 732 / 7090-3120 Fax: +43 / 732 / 7090-6301<br />E-Mail: kus@keba.com WWW: www.keba.com<br />-<br />To unsubscribe from this list: send the line "unsubscribe linux-kernel" in<br />the body of a message to majordomo@vger.kernel.org<br />More majordomo info at <a href="http://vger.kernel.org/majordomo-info.html">http://vger.kernel.org/majordomo-info.html</a><br />Please read the FAQ at <a href="http://www.tux.org/lkml/">http://www.tux.org/lkml/</a><br /><br /></pre></td><td width="32" rowspan="2" class="c" valign="top"><img src="/images/icornerr.gif" width="32" height="32" alt="\" /></td></tr><tr><td align="right" valign="bottom"> 聽 </td></tr><tr><td align="right" valign="bottom">聽</td><td class="c" valign="bottom" style="padding-bottom: 0px"><img src="/images/bcornerl.gif" width="32" height="32" alt="\" /></td><td class="c">聽</td><td class="c" valign="bottom" style="padding-bottom: 0px"><img src="/images/bcornerr.gif" width="32" height="32" alt="/" /></td></tr><tr><td align="right" valign="top" colspan="2"> 聽 </td><td class="lm">Last update: 2005-12-30 13:42 聽聽 [from the cache]<br />漏2003-2020 <a href="http://blog.jasper.es/"><span itemprop="editor">Jasper Spaans</span></a>|hosted at <a href="https://www.digitalocean.com/?refcode=9a8e99d24cf9">Digital Ocean</a> and my Meterkast|<a href="http://blog.jasper.es/categories.html#lkml-ref">Read the blog</a></td><td>聽</td></tr></table><script language="javascript" src="/js/styleswitcher.js" type="text/javascript"></script></body></html>