diff mbox series

[v6,5/5] xen: add debugtrace entry when entry count is wrapping

Message ID 20190909073557.16168-6-jgross@suse.com (mailing list archive)
State Superseded
Headers show
Series xen: debugtrace cleanup and per-cpu buffer support | expand

Commit Message

Jürgen Groß Sept. 9, 2019, 7:35 a.m. UTC
The debugtrace entry count is a 32 bit variable, so it can wrap when
lots of trace entries are being produced. Making it wider would result
in a waste of buffer space as the printed count value would consume
more bytes when not wrapping.

So instead of letting the count value grow to huge values let it wrap
and add a wrap counter printed in this situation. This will keep the
needed buffer space at today's value while avoiding to loose a way to
sort all entries in case multiple trace buffers are involved.

Signed-off-by: Juergen Gross <jgross@suse.com>
---
 xen/common/debugtrace.c | 33 +++++++++++++++++++++++++++++----
 1 file changed, 29 insertions(+), 4 deletions(-)

Comments

Jan Beulich Sept. 9, 2019, 8:19 a.m. UTC | #1
On 09.09.2019 09:35, Juergen Gross wrote:
> @@ -173,10 +177,23 @@ void debugtrace_printk(const char *fmt, ...)
>      nr = vsnprintf(buf, sizeof(buf), fmt, args);
>      va_end(args);
>  
> +    if ( count == DEBUGTRACE_COUNT_WRAP )
> +    {
> +        count = 0;
> +        wrap_cnt++;
> +    }
> +
>      if ( debugtrace_send_to_console )
>      {
> -        unsigned int n = scnprintf(cntbuf, sizeof(cntbuf), "%u ", ++count);
> +        unsigned int n;
> +
> +        if ( count == 0 )
> +        {
> +            n = scnprintf(cntbuf, sizeof(cntbuf), "wrap: %lu\n", wrap_cnt);
> +            console_serial_puts(cntbuf, n);
> +        }
>  
> +        n = scnprintf(cntbuf, sizeof(cntbuf), "%u ", ++count);
>          console_serial_puts(cntbuf, n);
>          console_serial_puts(buf, nr);
>      }

Just one minor remark: In this case you issue a "wrap" message at
start of day, ...

> @@ -184,8 +201,16 @@ void debugtrace_printk(const char *fmt, ...)
>      {
>          unsigned int cpu = debugtrace_per_cpu ? smp_processor_id() : 0;
>  
> -        if ( debugtrace_buf_empty || strcmp(buf, last_buf) )
> +        if ( debugtrace_buf_empty || wrap_cnt != data->wrap_cnt ||
> +             strcmp(buf, last_buf) )
>          {
> +            if ( wrap_cnt != data->wrap_cnt )
> +            {
> +                snprintf(cntbuf, sizeof(cntbuf), "wrap: %lu->%lu\n",
> +                         data->wrap_cnt, wrap_cnt);
> +                debugtrace_add_to_buf(cntbuf);
> +                data->wrap_cnt = wrap_cnt;
> +            }
>              debugtrace_buf_empty = false;
>              last_prd = data->prd;
>              last_count = ++count;

... whereas here one gets issued (as I'd expect it) only after the
first wrapping of "count".

Jan
Jürgen Groß Sept. 9, 2019, 8:22 a.m. UTC | #2
On 09.09.19 10:19, Jan Beulich wrote:
> On 09.09.2019 09:35, Juergen Gross wrote:
>> @@ -173,10 +177,23 @@ void debugtrace_printk(const char *fmt, ...)
>>       nr = vsnprintf(buf, sizeof(buf), fmt, args);
>>       va_end(args);
>>   
>> +    if ( count == DEBUGTRACE_COUNT_WRAP )
>> +    {
>> +        count = 0;
>> +        wrap_cnt++;
>> +    }
>> +
>>       if ( debugtrace_send_to_console )
>>       {
>> -        unsigned int n = scnprintf(cntbuf, sizeof(cntbuf), "%u ", ++count);
>> +        unsigned int n;
>> +
>> +        if ( count == 0 )
>> +        {
>> +            n = scnprintf(cntbuf, sizeof(cntbuf), "wrap: %lu\n", wrap_cnt);
>> +            console_serial_puts(cntbuf, n);
>> +        }
>>   
>> +        n = scnprintf(cntbuf, sizeof(cntbuf), "%u ", ++count);
>>           console_serial_puts(cntbuf, n);
>>           console_serial_puts(buf, nr);
>>       }
> 
> Just one minor remark: In this case you issue a "wrap" message at
> start of day, ...
> 
>> @@ -184,8 +201,16 @@ void debugtrace_printk(const char *fmt, ...)
>>       {
>>           unsigned int cpu = debugtrace_per_cpu ? smp_processor_id() : 0;
>>   
>> -        if ( debugtrace_buf_empty || strcmp(buf, last_buf) )
>> +        if ( debugtrace_buf_empty || wrap_cnt != data->wrap_cnt ||
>> +             strcmp(buf, last_buf) )
>>           {
>> +            if ( wrap_cnt != data->wrap_cnt )
>> +            {
>> +                snprintf(cntbuf, sizeof(cntbuf), "wrap: %lu->%lu\n",
>> +                         data->wrap_cnt, wrap_cnt);
>> +                debugtrace_add_to_buf(cntbuf);
>> +                data->wrap_cnt = wrap_cnt;
>> +            }
>>               debugtrace_buf_empty = false;
>>               last_prd = data->prd;
>>               last_count = ++count;
> 
> ... whereas here one gets issued (as I'd expect it) only after the
> first wrapping of "count".

Yes, I know. The reason I have done it this way was the possibility to
support debugtrace via console even in case of a zero-sized buffer in
future. I can point that out in the commit message.


Juergen
diff mbox series

Patch

diff --git a/xen/common/debugtrace.c b/xen/common/debugtrace.c
index 669b2102ab..f779ad36ed 100644
--- a/xen/common/debugtrace.c
+++ b/xen/common/debugtrace.c
@@ -15,11 +15,14 @@ 
 #include <xen/spinlock.h>
 #include <xen/watchdog.h>
 
+#define DEBUGTRACE_COUNT_WRAP 99999999
+
 /* Send output direct to console, or buffer it? */
 static volatile bool debugtrace_send_to_console;
 
 struct debugtrace_data {
     unsigned long prd;   /* Producer index. */
+    unsigned long wrap_cnt;
     char          buf[];
 };
 
@@ -72,6 +75,7 @@  static void debugtrace_dump_buffer(struct debugtrace_data *data,
     /* Print youngest portion of the ring. */
     data->buf[data->prd] = '\0';
     console_serial_puts(&data->buf[0], data->prd);
+    printk("wrap: %lu\n", data->wrap_cnt);
 
     memset(data->buf, '\0', debugtrace_bytes);
     data->prd = 0;
@@ -153,9 +157,9 @@  void debugtrace_printk(const char *fmt, ...)
 {
     static char buf[1024], last_buf[1024];
     static unsigned int count, last_count, last_cpu;
-    static unsigned long last_prd;
+    static unsigned long last_prd, wrap_cnt;
 
-    char          cntbuf[24];
+    char          cntbuf[50];
     va_list       args;
     unsigned long flags;
     unsigned int nr;
@@ -173,10 +177,23 @@  void debugtrace_printk(const char *fmt, ...)
     nr = vsnprintf(buf, sizeof(buf), fmt, args);
     va_end(args);
 
+    if ( count == DEBUGTRACE_COUNT_WRAP )
+    {
+        count = 0;
+        wrap_cnt++;
+    }
+
     if ( debugtrace_send_to_console )
     {
-        unsigned int n = scnprintf(cntbuf, sizeof(cntbuf), "%u ", ++count);
+        unsigned int n;
+
+        if ( count == 0 )
+        {
+            n = scnprintf(cntbuf, sizeof(cntbuf), "wrap: %lu\n", wrap_cnt);
+            console_serial_puts(cntbuf, n);
+        }
 
+        n = scnprintf(cntbuf, sizeof(cntbuf), "%u ", ++count);
         console_serial_puts(cntbuf, n);
         console_serial_puts(buf, nr);
     }
@@ -184,8 +201,16 @@  void debugtrace_printk(const char *fmt, ...)
     {
         unsigned int cpu = debugtrace_per_cpu ? smp_processor_id() : 0;
 
-        if ( debugtrace_buf_empty || strcmp(buf, last_buf) )
+        if ( debugtrace_buf_empty || wrap_cnt != data->wrap_cnt ||
+             strcmp(buf, last_buf) )
         {
+            if ( wrap_cnt != data->wrap_cnt )
+            {
+                snprintf(cntbuf, sizeof(cntbuf), "wrap: %lu->%lu\n",
+                         data->wrap_cnt, wrap_cnt);
+                debugtrace_add_to_buf(cntbuf);
+                data->wrap_cnt = wrap_cnt;
+            }
             debugtrace_buf_empty = false;
             last_prd = data->prd;
             last_count = ++count;