Skip to contentSkip to conversation

rt-tests: hackbench: fix for uninitialized start time

PATCH In review Ciprian Barbu 4 participants 8 messages Dec 12, 2013 – Dec 22, 2013

lore
Share & tools
lore
#0 lore raw

PATCH 1/1 rt-tests: hackbench: fix for uninitialized start time

Hello,

While playing around with hackbench I discovered that I would sometimes get an enormous time reported, even if the run time would be less than a second or so. The problem was that the struct timeval start was not initialized until after all children have been created. But if the program receives a signal before this is done, the start time is left uninitialized.

I propose that in such situations an error message be displayed, like the following patch does.

Please let me know if this is acceptable.

Regards,
/Ciprian

---

src/hackbench/hackbench.c 2013-12-12 16:24:01.945738814 +0200 renamed from src/hackbench/hackbench.c 2013-12-12 16:27:06.273731063 +0200 +8 -2
diff -rupN rt-tests/src/hackbench/hackbench.c rt-tests2/src/hackbench/hackbench.c
@@ -442,6 +442,7 @@ int main(int argc, char *argv[])
    struct timeval start, stop, diff;
    int readyfds[2], wakefds[2];
    char dummy;
+   int timer_started = 0;
    struct sched_param sp;
 
    process_options (argc, argv);
@@ -490,6 +491,7 @@ int main(int argc, char *argv[])
            }
 
        gettimeofday(&start, NULL);
+       timer_started = 1;
 
        /* Kick them off */
        if (write(wakefds[1], &dummy, 1) != 1) {
@@ -509,8 +511,12 @@ int main(int argc, char *argv[])
    gettimeofday(&stop, NULL);
 
    /* Print time... */
-   timersub(&stop, &start, &diff);
-   printf("Time: %lu.%03lu\n", diff.tv_sec, diff.tv_usec/1000);
+   if (timer_started) {
+       timersub(&stop, &start, &diff);
+       printf("Time: %lu.%03lu\n", diff.tv_sec, diff.tv_usec/1000);
+   } else {
+       fprintf(stderr, "No measurements available\n");
+   }
    free(child_tab);
    exit(0);
 }
#1 lore raw
Quoted 9 lines · On Thu, 12 Dec 2013 16:47:19 +0200 Ciprian Barbu <[email protected]>…

Hello,

While playing around with hackbench I discovered that I would sometimes get an enormous time reported, even if the run time would be less than a second or so. The problem was that the struct timeval start was not initialized until after all children have been created. But if the program receives a signal before this is done, the start time is left uninitialized.

Quoted 7 lines

I propose that in such situations an error message be displayed, like the following patch does.

Please let me know if this is acceptable.

Regards,
/Ciprian

Looks good to me. I've pulled it in for the next release.

Clark

#2 lore raw

3.12.5 CRASH/FREEZE

In reply to Ciprian Barbu

On startup, if USB webcam (uvcvideo) attached in usb-hole

NMI backtrace for cpu 1

CPU: 1 PID: 0 Comm: swapper/1 Not tainted 3.12.5-plx #6
Hardware name: PEGATRON CORPORATION SAISHIAT2/IPPCR-SS, BIOS 0308 10/31/2012
task: f60a4420 ti: f60b4000 task.ti: f60b4000
EIP: 0060:[<c13f3be5>] EFLAGS: 00200246 CPU: 1
EIP is at poll_idle+0x95/0xb0
EAX: 00000000 EBX: f67d13d8 ECX: 00000019 EDX: f60b4000
ESI: af9fbf64 EDI: 000000a7 EBP: f60b5f54 ESP: f60b5f44
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
CR0: 80050033 CR2: b7ec2000 CR3: 35768000 CR4: 000407b0
Stack:
 00000000 c1648af0 f67d13d8 c1648ae0 f60b5f78 c13f3ddf af9fbbd8 000000a7
 00000000 00000000 c1679f24 c1678a00 f67cedc0 f60b5f80 c100ba68 f60b5f8c
 c1084272 00000001 f60b5fb4 c1025018 02100800 00000000 00000000 360b5fb4
Call Trace:
 [<c13f3ddf>] cpuidle_idle_call+0x9f/0x1c0
 [<c100ba68>] arch_cpu_idle+0x8/0x20
 [<c1084272>] cpu_startup_entry+0xe2/0x110
 [<c1025018>] start_secondary+0x1a8/0x210
Code: 8d b6 00 00 00 00 3d ff ff ff 7f 77 e0 89 43 08 8b 45 f0 83 c4 04 5b 5e 5f
5d c3 8d 76 00 89 e2 81 e2 00 e0 ff ff f3 90 8b 42 08 <a8> 08 75 97 8b 42 08 f6
c4 02 75 8f eb ed 8d b6 00 00 00 00 8d
NMI backtrace for cpu 0
CPU: 0 PID: 35 Comm: irq/43-xhci_hcd Not tainted 3.12.5-plx #6
Hardware name: PEGATRON CORPORATION SAISHIAT2/IPPCR-SS, BIOS 0308 10/31/2012
task: f58f8da0 ti: f5900000 task.ti: f5900000
EIP: 0060:[<c1027c38>] EFLAGS: 00000046 CPU: 0
EIP is at default_send_IPI_mask_logical+0x78/0xa0
EAX: 00000c00 EBX: 03000000 ECX: c163d200 EDX: fffff000
ESI: 00000c00 EDI: 00000006 EBP: f5901ba8 ESP: f5901b94
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
CR0: 80050033 CR2: b7ec2417 CR3: 35166000 CR4: 000407b0
Stack:
 00000006 00000002 00002710 000026c8 c1641140 f5901bb8 c1027d70 00002710
 000026c8 f5901bc8 c1027f31 c15d69cd f67c1c60 f5901c14 c10a987b c1603e90
 000927c9 0000026b 0000026a 000026c8 aea0554e f5901bf0 00000000 f5901c14
Call Trace:
 [<c1027d70>] default_send_IPI_all+0x80/0x90
 [<c1027f31>] arch_trigger_all_cpu_backtrace+0x41/0x70
 [<c10a987b>] rcu_check_callbacks+0x2db/0x650
 [<c106491d>] ? scheduler_tick+0xad/0x120
 [<c1044f15>] update_process_times+0x45/0x60
 [<c109282a>] tick_handle_periodic+0x3a/0x1f0
 [<c10264d4>] smp_apic_timer_interrupt+0x54/0x90
 [<c1508042>] apic_timer_interrupt+0x2a/0x30
 [<c13a55b2>] ? inc_enq+0x12/0x170
 [<c13aa59c>] xhci_queue_isoc_tx_prepare+0x39c/0x950
 [<c10264d9>] ? smp_apic_timer_interrupt+0x59/0x90
 [<c139d35f>] xhci_urb_enqueue+0x22f/0x540
 [<c1375745>] usb_hcd_submit_urb+0x65/0x280
 [<c13e3029>] ? uvc_video_decode_isoc+0x149/0x220
 [<c13777a0>] usb_submit_urb+0x170/0x3a0
 [<c103cd06>] ? irq_exit+0x56/0x70
 [<c13e1ee8>] uvc_video_complete+0xb8/0xd0
 [<c1374625>] __usb_hcd_giveback_urb+0x45/0xa0
 [<c1374bd8>] usb_hcd_giveback_urb+0x38/0xf0
 [<c13a84cf>] handle_tx_event+0x3af/0xda0
 [<c103cd06>] ? irq_exit+0x56/0x70
 [<c10264d9>] ? smp_apic_timer_interrupt+0x59/0x90
 [<c15088a9>] ? common_interrupt+0x29/0x2e
 [<c13a9082>] xhci_irq+0x1a2/0x6c0
 [<c1508042>] ? apic_timer_interrupt+0x2a/0x30
 [<c13a95aa>] xhci_msi_irq+0xa/0x10
 [<c1084c31>] irq_forced_thread_fn+0x21/0x70
 [<c1085046>] irq_thread+0x106/0x220
 [<c1084c10>] ? irq_finalize_oneshot.part.40+0xc0/0xc0
 [<c1084cc0>] ? irq_thread_fn+0x40/0x40
 [<c1057110>] kthread+0xd0/0xe0
 [<c1084f40>] ? set_affinity_thread+0x140/0x140
 [<c15083b7>] ret_from_kernel_thread+0x1b/0x28
 [<c1057040>] ? kthread_flush_work_fn+0x10/0x10
Code: 80 e5 10 75 ee c1 e3 18 89 98 10 c3 ff ff 89 d0 09 f0 81 ce 00 04 00 00 83

fa 02 8b 15 44 d5 63 c1 0f 44 c6 89 82 00 c3 ff ff 57 <9d> 8b 5d f4 8b 75 f8 8b 7d fc 89 ec 5d c3 89 55 f0 ff 90 b4 00
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run:
71.797 msecs

---

3.2.53 - works fine :)

#3 lore raw

Re: 3.12.5 CRASH/FREEZE

Quoted 19 lines · * Pavel Vasilyev | 2013-12-13 00:29:52 [+0400]:

On startup, if USB webcam (uvcvideo) attached in usb-hole

NMI backtrace for cpu 0

CPU: 0 PID: 35 Comm: irq/43-xhci_hcd Not tainted 3.12.5-plx #6

[<c13aa59c>] xhci_queue_isoc_tx_prepare+0x39c/0x950
[<c139d35f>] xhci_urb_enqueue+0x22f/0x540
[<c1375745>] usb_hcd_submit_urb+0x65/0x280
[<c13777a0>] usb_submit_urb+0x170/0x3a0
[<c13e1ee8>] uvc_video_complete+0xb8/0xd0
[<c1374625>] __usb_hcd_giveback_urb+0x45/0xa0
[<c1374bd8>] usb_hcd_giveback_urb+0x38/0xf0
[<c13a84cf>] handle_tx_event+0x3af/0xda0
[<c13a9082>] xhci_irq+0x1a2/0x6c0
[<c13a95aa>] xhci_msi_irq+0xa/0x10
[<c1084c31>] irq_forced_thread_fn+0x21/0x70
[<c1085046>] irq_thread+0x106/0x220
[<c1057110>] kthread+0xd0/0xe0
[<c15083b7>] ret_from_kernel_thread+0x1b/0x28

This looks like uvc is resubmitting the URB on completion. Nothing unusual. Howver it seems that then CPU gets stuck in xhci_queue_isoc_tx_prepare() for some reason. Could you try map c13aa59c to the source line? Something like
addr2lin -e xhci-hcd.ko -i c13aa59c

should do the trick but of the module of this trace.
What does the -plx stand for in localversion? Do you have any custom patches on your kernel?

Sebastian

#4 lore raw

Re: 3.12.5 CRASH/FREEZE

20.12.2013 18:10, Sebastian Andrzej Siewior пишет:

Quoted 22 lines · * Pavel Vasilyev | 2013-12-13 00:29:52 [+0400]:
Quoted 4 lines

On startup, if USB webcam (uvcvideo) attached in usb-hole

NMI backtrace for cpu 0

Quoted 16 lines
CPU: 0 PID: 35 Comm: irq/43-xhci_hcd Not tainted 3.12.5-plx #6

[<c13aa59c>] xhci_queue_isoc_tx_prepare+0x39c/0x950
[<c139d35f>] xhci_urb_enqueue+0x22f/0x540
[<c1375745>] usb_hcd_submit_urb+0x65/0x280
[<c13777a0>] usb_submit_urb+0x170/0x3a0
[<c13e1ee8>] uvc_video_complete+0xb8/0xd0
[<c1374625>] __usb_hcd_giveback_urb+0x45/0xa0
[<c1374bd8>] usb_hcd_giveback_urb+0x38/0xf0
[<c13a84cf>] handle_tx_event+0x3af/0xda0
[<c13a9082>] xhci_irq+0x1a2/0x6c0
[<c13a95aa>] xhci_msi_irq+0xa/0x10
[<c1084c31>] irq_forced_thread_fn+0x21/0x70
[<c1085046>] irq_thread+0x106/0x220
[<c1057110>] kthread+0xd0/0xe0
[<c15083b7>] ret_from_kernel_thread+0x1b/0x28
Quoted 3 lines

This looks like uvc is resubmitting the URB on completion. Nothing unusual. Howver it seems that then CPU gets stuck in xhci_queue_isoc_tx_prepare() for some reason. Could you try map c13aa59c

Same bug if attach to ehci hub.

ksoftird/0 process of loading the CPU upto 100% Sometimes process irq17/0 - ehci_hcd or xhci_hcd. After taking the camera out of the socket, the load does not fall, keyboard and console blocked

Quoted 6 lines

to the source line? Something like
addr2lin -e xhci-hcd.ko -i c13aa59c

should do the trick but of the module of this trace.
What does the -plx stand for in localversion? Do you have any custom patches on your kernel?

No patches, just local flag.

Signature · 1 line
                                                         Pavel.
#5 lore raw

Re: 3.12.5 CRASH/FREEZE

Quoted 6 lines · Pavel Vasilyev

Same bug if attach to ehci hub.

ksoftird/0 process of loading the CPU upto 100% Sometimes process irq17/0 - ehci_hcd or xhci_hcd. After taking the camera out of the socket, the load does not fall, keyboard and console blocked

Okay, but this problem is unique to your webcam. Keyboard & mice to work as usual?
Could please provide me the addr2line either for the ehci or xhci? I've been browsing to the code and I didn't see anything obvious.

Sebastian

#6 lore raw

Re: 3.12.5 CRASH/FREEZE

20.12.2013 19:05, Sebastian Andrzej Siewior пишет:

Quoted 13 lines · Pavel Vasilyev
Quoted 6 lines

Same bug if attach to ehci hub.

ksoftird/0 process of loading the CPU upto 100% Sometimes process irq17/0 - ehci_hcd or xhci_hcd. After taking the camera out of the socket, the load does not fall, keyboard and console blocked

Okay, but this problem is unique to your webcam. Keyboard & mice to work as usual?
Could please provide me the addr2line either for the ehci or xhci? I've been browsing to the code and I didn't see anything obvious.

Too many bugs, too many computers ...

3.12.5-rt7 work ONLY in UP-mode!!! cmdline: nosmp maxcpus=1

In SMP mode, problems arise in different places on different computers. On Intel Atom - USB, webcam and console. On the Opteron 285 system does not boot, can't mount devtmpfs, XFS partitions ...

I can not get to catch the error and find a place neither in debug mode or in normal. Because everything is frozen completely, and get to the console or logs is not possible.
I described one situation where had run top and see that the process ksoftirqd/0 use CPU upto 100%

P.S.

    3.12.5-rt7 still work Basic-RT mode.
Signature · 5 lines
                                                         Pavel.
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
#7 lore raw

Re: 3.12.5 CRASH/FREEZE

In reply to Sebastian Andrzej Siewior

20.12.2013 19:05, Sebastian Andrzej Siewior пишет:

Quoted 1 line · Pavel Vasilyev

... The last two years I have worked with 3.2 kernel and patches for it. Recently, we have a new equipment that partially works with version 3.2.53. Therefore it was decided to move to version 3.12. What was my surprise that none of the 15 (or old models, or new )computers does not start with the same .configs on a new version of the kernel and rt-patches. :)

Signature · 1 line
                                                         Pavel.