timer_test failed on -O2

[GoogleCodeExporter]

What steps will reproduce the problem?
1.r13274,nonvga_debug,gcc 4.8.2,-O2
2.apply patch for debug output:
Index: src/arch/x86/kernel/irq_handler.c
===================================================================
--- src/arch/x86/kernel/irq_handler.c   (revision 13274)
+++ src/arch/x86/kernel/irq_handler.c   (working copy)
@@ -24,7 +24,7 @@
    {
        int irq = regs->trapno - 0x20;

-       ipl_enable();
+       ipl_enable("irq");

        irq_dispatch(irq);

@@ -35,7 +35,7 @@
         * level till switched to lower critical level.
         */

-       ipl_disable();
+       ipl_disable("irq");

        i8259_send_eoi(irq);

Index: src/include/hal/ipl.h
===================================================================
--- src/include/hal/ipl.h   (revision 13274)
+++ src/include/hal/ipl.h   (working copy)
@@ -26,12 +26,13 @@
  */
 extern void ipl_init(void);

+#include <kernel/printk.h>
 /**
  * Set the lowest interrupt priority level allowing all IRQs.
  *
  * @sa ipl_disable()
  */
-#define ipl_enable()  ipl_init()
+#define ipl_enable(...)  (printk("en " __VA_ARGS__ "\n"), ipl_init())

 /**
  * Sets the maximal interrupt priority level cutting off all IRQs on the CPU.
@@ -39,7 +40,7 @@
  * @sa ipl_enable()
  * @sa ipl_save()
  */
-#define ipl_disable() ((void) ipl_save())
+#define ipl_disable(...) ((void) ipl_save(), printk("dis " __VA_ARGS__ "\n"))

 /**
  * Sets the maximal interrupt priority level cutting off all IRQs on the CPU.
Index: src/kernel/critical.c
===================================================================
--- src/kernel/critical.c   (revision 13274)
+++ src/kernel/critical.c   (working copy)
@@ -26,6 +26,7 @@
    ipl_t ipl;

    ipl = ipl_save();
+   printk("disp %u: ", ipl);

    while ((d = *pp) && !((mask = d->mask) & count)) {
        *pp = d->next;
@@ -35,6 +36,7 @@
        d->dispatch();
    }

+   printk("end-disp %u\n", ipl);
    ipl_restore(ipl);
 }

Index: src/kernel/softirq.c
===================================================================
--- src/kernel/softirq.c    (revision 13274)
+++ src/kernel/softirq.c    (working copy)
@@ -90,9 +90,9 @@

                    softipl = (0x1ul << nr) - 1; /* mask out lower softirqs */

-                   ipl_enable();
+                   ipl_enable("softirq_dispatch");
                    handler(nr, data);
-                   ipl_disable();
+                   ipl_disable("softirq_dispatch");
                }
            }
        }
Index: src/kernel/time/timer/strategy/list_timer.c
===================================================================
--- src/kernel/time/timer/strategy/list_timer.c (revision 13274)
+++ src/kernel/time/timer/strategy/list_timer.c (working copy)
@@ -15,6 +15,7 @@

 static DLIST_DEFINE(sys_timers_list);

+#include <kernel/printk.h>
 void timer_strat_start(struct sys_timer *tmr) {
    ipl_t ipl;

@@ -23,6 +24,7 @@
    dlist_head_init(&tmr->lnk);

    ipl = ipl_save();
+   printk("tmr_start_ipl %u\n", ipl);
    /* new timer added to begining of the list to sure, that it will not 
     * be processed. Otherwise, if a new timer added while handling some 
     * other one, it will be processed during same timer_strat_sched 
@@ -62,6 +64,7 @@
    timer_set_stopped(tmr);

    ipl = ipl_save();
+   printk("tmr_stop_ipl %u\n", ipl);
    dlist_del(&tmr->lnk);
    ipl_restore(ipl);
 }
3.

What is the expected output? What do you see instead?
...
disp 2: end-disp 2
disp 2: end-disp 2
disp 2: end-disp 2
disp 2: end-disp 2
disp 2: end-disp 2
disp 2: end-disp 2
disp 2: end-disp 2
disp 6: end-disp 6
disp 2: end-disp 2
disp 6: end-disp 6
disp 6: end-disp 6
disp 6: end-disp 6
disp 2: end-disp 2
. done
    test: running embox.test.posix.getopt_test .............. done
    test: running embox.test.stdio.printf_test ......... done
    test: running embox.test.recursion . done
    test: running embox.test.kernel.timer_test tmr_start_ipl 2
disp 6: end-disp 6
tmr_start_ipl 2
disp 6: end-disp 6

Please use labels and text to provide additional information.

Original issue reported on code.google.com by ki.stfu on 3 Apr 2014 at 12:32

[GoogleCodeExporter]

Original comment by ki.stfu on 3 Apr 2014 at 12:33

Attachments:

• issue687.log

[GoogleCodeExporter]

it works fine before r13084

Original comment by ki.stfu on 6 May 2014 at 3:36

[GoogleCodeExporter]

it doesn't working after r13084
to fix module initialization apply changes introduced in r13132-r13134 with
$ svn merge -r13131:13134 .

Original comment by ki.stfu on 8 May 2014 at 8:23

[GoogleCodeExporter]

btw, try this
Index: src/arch/x86/kernel/context_switch.S
===================================================================
--- src/arch/x86/kernel/context_switch.S    (revision 13691)
+++ src/arch/x86/kernel/context_switch.S    (working copy)
@@ -31,6 +31,7 @@
    movl CTX_X86_ESP(%ecx), %esp   /* Restore esp */
    push CTX_X86_EFLAGS(%ecx)      /* Push saved flags */
    popf                           /* Restore flags */
+   sti
    movl CTX_X86_EIP(%ecx), %eax   /* Get eip */
    push %eax                      /* Restore it as return address */

Original comment by ki.stfu on 8 May 2014 at 9:00

[GoogleCodeExporter]

Last suggestion was really close.
There is no initialization order difference between specified commits. 
But when timer_test started interrupts was already disabled. So it was broken 
earlier.
I've found out that with O2 __schedule stores ipl in esi register, and exactly 
this register wasn't properly restored in context_switch!
Fix introduced in r14105. Compiled with O2 timer_test isn't fails anymore.

Original comment by drakon.m...@gmail.com on 19 Jun 2014 at 3:05

• Changed state: Fixed