[Xenomai-core] Re: [Xenomai-help] task not being scheduled

[Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org>]

[-- Attachment #1: Type: text/plain, Size: 1450 bytes --]

Jeff Weber wrote:
> On Wednesday 28 February 2007 08:20, Gilles Chanteperdrix wrote:
> 
>>Jan Kiszka wrote:
>>
>>
>>>Jeff, you have the ultimate test case now. Will you have some time to
>>>run that test on your box so that we can quickly find and resolve the
>>>bug?
> 
> 
> Yes.  I've rebuilt my kernel with the linked list scheduler, but I've saved 
> the previous heap scheduler config.  I will recreate the bug config, and 
> await a patch or instrumentation.
> 
>>Is it possible to get a simplified version of the application you are
>>running with only timer-related events ? Some kind of model that I could
>>quietly run in the simulator ?
> 
> That will be more difficult.  The application requires a custom kernel module, 
> and has many dependencies upon our hardware.  Further, the app is written in 
> C++, which I understand is not compatible with the simulator.
> 
> Let me know if you would like to move this discussion off the xenomai-help 
> list, to xenomai-core, or a private email discussion.
> 
> And again, thanks for taking the time to look at my trace, config and 
> recommend a solution.  It was causing considerable frustration on this end.

Ok. Following up on xenomai-core. Find attached a not too subtle
instrumentation that saves the state of the heap after each elementary
operation. This history is then dumped with printk on xntrace freeze.

-- 
                                                 Gilles Chanteperdrix

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: xeno-trace-bheap.diff --]
[-- Type: text/x-patch; name="xeno-trace-bheap.diff", Size: 6583 bytes --]

Index: include/nucleus/bheap.h
===================================================================
--- include/nucleus/bheap.h	(révision 2730)
+++ include/nucleus/bheap.h	(copie de travail)
@@ -25,6 +25,12 @@
 
 /* Priority queue implementation, using a binary heap. */
 
+typedef enum {
+	BHEAP_INSERT,
+	BHEAP_DELETE,
+	BHEAP_GETHEAD,
+} bheap_op_t;
+ 
 typedef unsigned long long bheap_key_t;
 
 typedef struct bheaph {
@@ -66,11 +72,18 @@
     __internal_bheap_gethead(_bheap);           \
 })
 
+void bheap_s_init(void);
+
+void bheap_save_push(bheap_t *q, bheap_op_t op, bheaph_t *elem);
+
+void bheap_ops_dump(void);
+
 static inline bheaph_t *__internal_bheap_gethead(bheap_t *heap)
 {
     if (heap->last == 1)
         return NULL;
 
+    bheap_save_push(heap, BHEAP_GETHEAD, heap->elems[1]);
     return heap->elems[1];
 }
 
@@ -158,6 +171,7 @@
     bheaph_pos(holder) = heap->last;
     ++heap->last;
     bheap_up(heap, holder);
+    bheap_save_push(heap, BHEAP_INSERT, holder);
     return 0;
 }
 
@@ -182,6 +196,7 @@
         bheaph_pos(lasth) = bheaph_pos(holder);
         bheap_down(heap, lasth);
     }
+    bheap_save_push(heap, BHEAP_DELETE, holder);
 
     return 0;
 }
Index: ksrc/nucleus/timer.c
===================================================================
--- ksrc/nucleus/timer.c	(révision 2730)
+++ ksrc/nucleus/timer.c	(copie de travail)
@@ -755,6 +755,9 @@
 
 void xntimer_set_aperiodic_mode(void)
 {
+#if defined(CONFIG_XENO_OPT_TIMER_HEAP)
+	bheap_s_init();
+#endif
 	nktimer = &timer_ops_aperiodic;
 }
 
@@ -771,3 +774,166 @@
 EXPORT_SYMBOL(xntimer_get_date);
 EXPORT_SYMBOL(xntimer_get_timeout);
 EXPORT_SYMBOL(nktimer);
+
+#if defined(CONFIG_XENO_OPT_TIMER_HEAP)
+typedef struct {
+	unsigned sz;
+	unsigned last;
+	bheaph_t elems[CONFIG_XENO_OPT_TIMER_HEAP_CAPACITY + 1];
+/* indexing starts at 1	*/
+} bheap_save_t;
+
+#define BHEAP_SAVE_SIZE 256
+typedef struct {
+	unsigned head;
+	unsigned tail;
+	struct {
+		bheap_op_t op;
+		unsigned long long ts;
+		bheap_save_t save;
+	} array [BHEAP_SAVE_SIZE];
+} bheap_s_t;
+
+bheap_s_t *_bheap_s[2], *bheap_s;
+
+static void bheap_save(bheap_save_t *save, bheap_t *q)
+{
+	unsigned i;
+	save->sz = q->sz;
+	save->last = q->last;
+	for (i = 1; i < save->last; i++)
+		save->elems[i] = *(q->elems[i]);
+}
+
+void bheap_s_init(void)
+{
+	_bheap_s[0] = vmalloc(sizeof(bheap_s_t));
+	BUG_ON(!_bheap_s[0]);
+	_bheap_s[0]->head = _bheap_s[0]->tail = 0;
+	_bheap_s[1] = vmalloc(sizeof(bheap_s_t));
+	BUG_ON(!_bheap_s[1]);
+	_bheap_s[1]->head = _bheap_s[1]->tail = 0;
+	bheap_s = _bheap_s[0];
+}
+
+void bheap_save_push(bheap_t *q, bheap_op_t op, bheaph_t *elem)
+{
+	if (bheap_s->tail == bheap_s->head + BHEAP_SAVE_SIZE)
+		bheap_s->head++;
+	bheap_s->array[bheap_s->tail % BHEAP_SAVE_SIZE].ts = xnarch_get_cpu_tsc();
+	bheap_s->array[bheap_s->tail % BHEAP_SAVE_SIZE].op = op;
+	bheap_s->array[bheap_s->tail % BHEAP_SAVE_SIZE].save.elems[0]=*elem;
+	bheap_save(&bheap_s->array[bheap_s->tail % BHEAP_SAVE_SIZE].save, q);
+	bheap_s->tail++;
+}
+
+static int ts_convert(char *buf, size_t sz, unsigned long long ts)
+{
+	unsigned long long ns = xnarch_tsc_to_ns(ts);
+	unsigned hrs, mins, secs, nsecs;
+	nsecs = do_div(ns, 1000000000);
+	secs = ns;
+	mins = secs / 60;
+	secs %= 60;
+	hrs = mins / 60;
+	mins %= 60;
+	return snprintf(buf, sz, "%3u:%02u:%02u.%09u", hrs, mins, secs, nsecs);
+}
+
+static int bheaph_prn(char *buf, size_t sz, const bheaph_t *const holder)
+{
+	return ts_convert(buf, sz, holder->key);
+}
+
+static void
+bheap_dumper_visit (bheap_save_t *heap,
+                    bheaph_t *node,
+                    int (*prn)(char *, size_t, const bheaph_t *const),
+                    const char *blank,
+                    unsigned blank_sz,
+                    char *buf,
+                    unsigned indent,
+                    unsigned len)
+{
+	unsigned pos = 2 * node->pos + 1;
+
+	if(pos < heap->last) {
+		bheaph_t *child = &heap->elems[pos];
+		if(blank_sz >= (unsigned) (buf-blank)) {
+			snprintf(buf, len+2, "%*s\n", (int) len+1, "bug!");
+			printk("%s", buf-blank_sz);
+		} else
+			bheap_dumper_visit(heap, child, prn, blank,
+					   blank_sz+indent, buf, indent, len);
+	}
+	
+	(*prn)(buf, len+1, node);
+	buf[len] = '\n';
+	buf[len+1] = '\0';
+	
+	printk("%s", buf-blank_sz);
+
+	--pos;
+	if(pos < heap->last) {
+		bheaph_t *child = &heap->elems[pos];
+		if(blank_sz >= (unsigned) (buf-blank)) {
+			snprintf(buf, len+2, "%*s\n", (int) len+1, "bug!");
+			printk("%s", buf-blank_sz);
+		} else
+			bheap_dumper_visit(heap, child, prn, blank,
+					   blank_sz+indent, buf, indent, len);
+	}
+}
+
+static void
+bheap_s_dump(bheap_save_t *heap,
+	     int (*prn)(char *, size_t, const bheaph_t *const),
+	     unsigned margin,
+	     unsigned indent,
+	     unsigned len)
+{
+	if (heap->last == 1) {
+		printk("%s", "Empty.\n");
+	} else {
+		size_t blank_sz = (fls(heap->last - 1) + 1) * indent + margin;
+		char buffer[blank_sz+len+2];
+		memset(buffer, ' ', blank_sz);
+
+		bheap_dumper_visit(heap, &heap->elems[1], prn, buffer, margin,
+				   buffer+blank_sz, indent, len);
+	}
+}
+
+void bheap_ops_dump(void)
+{
+	static const char *ops [] = {
+		[BHEAP_INSERT] = "insert",
+		[BHEAP_DELETE] = "delete",
+		[BHEAP_GETHEAD]= "gthead"
+	};
+	bheap_s_t *cur_s;
+	unsigned i;
+	spl_t s;
+
+	xnlock_get_irqsave(&nklock, s);
+	cur_s = bheap_s;
+	bheap_s = bheap_s == _bheap_s[0] ? _bheap_s[1] : _bheap_s[0];
+	xnlock_put_irqrestore(&nklock, s);
+
+	for(i = cur_s->head % BHEAP_SAVE_SIZE;
+	    i < cur_s->tail % BHEAP_SAVE_SIZE;
+	    i++) {
+		char bts[20], bkey[20];
+		ts_convert(bts, sizeof(bts), cur_s->array[i].ts);
+		ts_convert(bkey, sizeof(bkey),
+			   cur_s->array[i].save.elems[0].key);
+		
+		printk("%s: %s %s\n", bts, ops[cur_s->array[i].op], bkey);
+		bheap_s_dump(&cur_s->array[i].save, bheaph_prn, 8, 4, 19);
+		printk("\n");
+	}
+
+	cur_s->head = cur_s->tail = 0;
+}
+
+#endif
Index: ksrc/nucleus/shadow.c
===================================================================
--- ksrc/nucleus/shadow.c	(révision 2730)
+++ ksrc/nucleus/shadow.c	(copie de travail)
@@ -1330,6 +1330,9 @@
 		break;
 
 	case __xntrace_op_user_freeze:
+#if defined(CONFIG_XENO_OPT_TIMER_HEAP)
+		bheap_ops_dump();
+#endif
 		err = xnarch_trace_user_freeze(__xn_reg_arg2(regs),
 					       __xn_reg_arg3(regs));
 		break;