Re: Strange interaction between latencytop and the scheduler

["Török Edwin" <edwintorok@gmail.com>]

Török Edwin wrote:
>   
>> The performance aspect... collecting the data isn't cheap (which is
>> why it's made a sysctl),
>> I still plan to look at optimizing it but it won't ever be free.
>>     
>
> Yes, I understand that. Is there a way latencytop could track its own
> overhead? I suppose it would lead to more accurate results
> (not that there would be anything wrong with the current ones).
>   

Latencytop userspace tool shows latencies > 0.1 msec, thus capturing
backtraces for latencies <0.1msec could be avoided.
If I apply the patch below, then enabling latencytop doesn't freeze X
when running the "10-threads doing infloop usleep(1)" test.
Still, I don't want to loose track of the latencies we didn't collect
backtraces for, so I added a special "untraced" category, reported as
first line in /proc/latency_stats. If needed, instead of hardcoding the
threshold, it could be made a sysctl, or set via writing to
/proc/latency_stats,...

While I am running the test-program:
$ grep untraced /proc/latency_stats
4875605 5120414 49 untraced

On an idle system:
$ grep untraced /proc/latency_stats
532 3287 47 untraced
$ grep untraced /proc/latency_stats
853 5778 47 untraced
$ grep untraced /proc/latency_stats
950 6788 47 untraced
$ grep untraced /proc/latency_stats
1343 9977 49 untraced
$ grep untraced /proc/latency_stats
1448 11075 49 untraced

Best regards,
--Edwin

---
latencytop.c |   19 ++++++++++++++++++-
 1 file changed, 18 insertions(+), 1 deletion(-)
--- /tmp/linux-2.6.24-rc8/kernel/latencytop.c    2008-01-24
11:27:32.727487585 +0200
+++ kernel/latencytop.c    2008-01-24 10:42:25.000000000 +0200
@@ -24,8 +24,11 @@
 static DEFINE_SPINLOCK(latency_lock);
 
 #define MAXLR 128
+/* we are not interested in latencies less than 0.1msec, so
+ * don't get backtraces for latencies <0.05msec.*/
+#define LATENCY_TRACE_THRESHOLD 50
 static struct latency_record latency_record[MAXLR];
-
+static struct latency_record untraced;
 int latencytop_enabled;
 
 void clear_all_latency_tracing(struct task_struct *p)
@@ -47,6 +50,7 @@
 
     spin_lock_irqsave(&latency_lock, flags);
     memset(&latency_record, 0, sizeof(latency_record));
+    memset(&untraced, 0, sizeof(untraced));
     spin_unlock_irqrestore(&latency_lock, flags);
 }
 
@@ -124,6 +128,15 @@
     if (inter && usecs > 5000)
         return;
 
+    if(usecs < LATENCY_TRACE_THRESHOLD) {
+        /* don't get stacktrace for very low latencies */
+        untraced.time += usecs;
+        if(usecs > untraced.max)
+            untraced.max = usecs;
+        untraced.count++;
+        return;
+    }
+
     memset(&lat, 0, sizeof(lat));
     lat.count = 1;
     lat.time = usecs;
@@ -177,6 +190,10 @@
 
     seq_puts(m, "Latency Top version : v0.1\n");
 
+    seq_printf(m, "%i %li %li untraced \n",
+            untraced.count,
+            untraced.time,
+            untraced.max);
     for (i = 0; i < MAXLR; i++) {
         if (latency_record[i].backtrace[0]) {
             int q;