long boot delays caused by 070ad7e7 floppy change

Jiri,

One of my test systems has a new 20s+ boot delay in 3.5rc* It takes the floppy driver that long to determine I don't have a floppy

[    2.386322] calling  floppy_init+0x0/0xe46 @ 1
[    2.448977] Refined TSC clocksource calibration: 2594.106 MHz.
[    2.449021] Switching to clocksource tsc
[   22.371560] floppy0: no floppy controllers found
[   22.371676] initcall floppy_init+0x0/0xe46 returned -19 after 19553621 usecs

In older kernels the delay is only about 3s.

I tracked it down to

commit 070ad7e793dc6ff753ee682ef7790b3373b471f6

Author: Jiri Kosina <[email protected]>
Date:   Fri May 18 13:50:25 2012 +0200

floppy: convert to delayed work and single-thread wq

The problem is not completely stable, a bisect actually doesn't find it and reverting the patch on current HEAD also doesn't help.

However when setting the tree manually to one commit before yours the problem is gone and adding your patch adds it.

I think the floppy init should run asynchronous, but it would be still good to make this faster again. Since block devices need to be synchronized at end of boot there is no way to hide a 20s delay completely.

-Andi

[email protected] -- Speaking for myself only

Can you enable debug output ("floppy=debug" iirc) to give more details of what happens leading up to the delay? Maybe the timing of the debug messages would give some hints too..

The fact that reverting the patch on current -git doesn't actually help makes me curious. And means that we can't fix it by reverting, so we really do have to figure out what's going on.

Linus

I'm seeing the same issue, so I've given this a try. Here are the messages printed when floppy debugging is enabled:

[    0.000000] floppy0: Setting flag 0x1
...
[    0.703201] 00:07: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.703506] Non-volatile memory driver v1.3
[    0.714318] floppy0: reschedule timeout lock fdc
[    1.651396] Refined TSC clocksource calibration: 2698.759 MHz.
[    1.651548] Switching to clocksource tsc
[   20.729798] floppy0: reschedule timeout do wakeup
[   20.732654] floppy0: no floppy controllers found
[   20.733220] loop: module loaded
[   20.733394] ahci 0000:00:1f.2: version 3.0
[   20.733430] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X

The 'reschedule timeout' messages are only printed when debugging is enabled. Hopefully that can give someone a hint as to what's going on?

Calvin Walton <[email protected]>

Ok, that 20 s timeout is a hint.

20s is the floppy "max timeout" value, and it's used in various places. HOWEVER. The "lock fdc" case absolutely should not be using that timeout. It should use the floppy "UDP->timeout" value, which should be just 3s. Which is still a long time, but not nearly as long as that.

Can you add a DPRINT() to the lock_fdc() function just before calling reschedule_timeout() to print out what the "drive" is? Something like yhhis (whitespace-damaged due to cut-and-paste):

    diff --git a/drivers/block/floppy.c b/drivers/block/floppy.c
    index cce7df367b79..00b52cef9d22 100644
    --- a/drivers/block/floppy.c
    +++ b/drivers/block/floppy.c
    @@ -876,6 +876,7 @@ static int lock_fdc(int drive, bool interruptible)

     	command_status = FD_COMMAND_NONE;

    +	DPRINT("lock_fdc: %d (out of %d)\n", drive, N_DRIVE);
     	reschedule_timeout(drive, "lock fdc");
     	set_fdc(drive);
     	return 0;

because maybe the 'drive' variable is crap there. In fact, add a

        WARN_ON_ONCE(dive < 0 || drive >= N_DRIVE);

in there too. Because if it is out of range, I'd want to see the call chain.

(And you still need floppy=debug to see that debug message, of course).

Linus

Ok, here's the dmesg output that I get:

[    0.661966] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled
[    0.682589] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.703303] 00:07: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.703599] Non-volatile memory driver v1.3
[    0.714316] floppy0: lock_fdc: -1 (out of 8)
[    0.714462] ------------[ cut here ]------------
[    0.714606] WARNING: at drivers/block/floppy.c:880 lock_fdc.isra.30+0x156/0x170()
[    0.717372] Hardware name: EX58-DS4
[    0.717511] Modules linked in:
[    0.717649] Pid: 1, comm: swapper/0 Not tainted 3.5.0-rc4-00230-g15114c7-dirty #21
[    0.717872] Call Trace:
[    0.718010]  [<ffffffff810686aa>] warn_slowpath_common+0x7a/0xb0
[    0.718154]  [<ffffffff810686f5>] warn_slowpath_null+0x15/0x20
[    0.718306]  [<ffffffff813e3d96>] lock_fdc.isra.30+0x156/0x170
[    0.718448]  [<ffffffff813e46f1>] user_reset_fdc+0x11/0x80
[    0.718592]  [<ffffffff81cbb854>] floppy_init+0x7d7/0xe15
[    0.718737]  [<ffffffff81cbb07d>] ? set_cmos+0x6e/0x6e
[    0.718879]  [<ffffffff810001ba>] do_one_initcall+0x3a/0x160
[    0.719024]  [<ffffffff81c95c4f>] kernel_init+0x101/0x185
[    0.719169]  [<ffffffff81c955c5>] ? do_early_param+0x87/0x87
[    0.719317]  [<ffffffff81760d94>] kernel_thread_helper+0x4/0x10
[    0.719460]  [<ffffffff81c95b4e>] ? start_kernel+0x32f/0x32f
[    0.719604]  [<ffffffff81760d90>] ? gs_change+0xb/0xb
[    0.719748] ---[ end trace 16b38434e9defc9e ]---
[    0.719888] floppy0: reschedule timeout lock fdc
[    1.651398] Refined TSC clocksource calibration: 2698.759 MHz.
[    1.651551] Switching to clocksource tsc
[   20.729857] floppy0: reschedule timeout do wakeup
[   20.730009] floppy0: no floppy controllers found
[   20.730578] loop: module loaded
[   20.730746] ahci 0000:00:1f.2: version 3.0
[   20.730782] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X

when using this debugging patch:

index cce7df3..8a41259 100644
@@ -876,6 +876,9 @@ static int lock_fdc(int drive, bool interruptible)
 
 	command_status = FD_COMMAND_NONE;
 
+	DPRINT("lock_fdc: %d (out of %d)\n", drive, N_DRIVE);
+	WARN_ON_ONCE(drive < 0 || drive >= N_DRIVE);
+
 	reschedule_timeout(drive, "lock fdc");
 	set_fdc(drive);
 	return 0;

Calvin Walton <[email protected]>

Ok, thanks. That -1 definitely explains the long delay. It's using "drive=-1" because it has no actual drive number, just the *controller* number.

And the backtrace shows what's going on too: it's the

  user_reset_fdc(-1, FD_RESET_ALWAYS, false);

that passes in -1 as the floppy controller number.

Ugh.

It looks like the code meant for -1 to mean "regular delay" (current_reqD), and -2 to mean MAXTIMEOUT. For some reason the "-1" logic has gotten screwed.

Linus

I am still trying to understand the exact situation.

Andi, do I understand you correctly that even if you revert 070ad7e793dc on top of current Linus' tree, you are still seeing the 20 second delay inside the initcall?

Jiri Kosina
SUSE Labs

Correct. Here's the debug output with just reverted (without Linus patch):

[    2.489559] calling  floppy_init+0x0/0xe46 @ 1
[    2.504363] floppy0: lock_fdc: -1 (out of 8)
[    2.504410] floppy0: reschedule timeout lock fdc
[   22.498784] floppy0: reschedule timeout do wakeup
[   22.498811] floppy0: no floppy controllers found
[   22.498944] initcall floppy_init+0x0/0xe46 returned -19 after

19577158 usecs

So it looks like current_reqD still exists, and sets the drive to "current_drive". Which *should* be 0, as far as I can tell. In fact, since "current_drive" is printed out by DPRINTK(), we *know* it's 0 (it's the "0" in the "floppy0:" message).

But how the heck does it pick that bogus 20 second delay then? The -1 should have been caught by

        if (drive == current_reqD)
                drive = current_drive;

and then we should have used the regular delay for drive 0.

Jiri, any ideas?

Linus

I am not seeing how this could be happening at the moment. I am also a bit puzzled by Andi's statement that reverting the conversion to the single wq is not fixing it.

Have we by any chance changed anything in wq processing during early bootup lately?

Calvin, Andi, could you please dump the value of UDP->timeout in __reschedule_timeout(), please?

index cce7df3..9850120 100644
@@ -675,8 +675,11 @@ static void __reschedule_timeout(int drive, const char *message)
 	if (drive < 0 || drive >= N_DRIVE) {
 		delay = 20UL * HZ;
 		drive = 0;
-	} else
+	} else {
+		DPRINT("__reschedule_timeout: setting timeout to %ld\n",
+				UDP->timeout);
 		delay = UDP->timeout;
+	}
 
 	queue_delayed_work(floppy_wq, &fd_timeout, delay);
 	if (UDP->flags & FD_DEBUG)

Jiri Kosina
SUSE Labs

[    2.496493] calling  floppy_init+0x0/0xe46 @ 1
[    2.511303] floppy0: lock_fdc: -1 (out of 8)
[    2.511346] floppy0: __reschedule_timeout: setting timeout to 750
[    2.511372] floppy0: reschedule timeout lock fdc
[   22.501757] floppy0: reschedule timeout do wakeup
[   22.501784] floppy0: no floppy controllers found
[   22.501919] initcall floppy_init+0x0/0xe46 returned -19 after

19573258 usecs

-Andi

Ahhah. And you have CONFIG_HZ250 set, don't you?

So it's actually asking for a 3-second timeout like it should.

But that actual timeout is too damn reliably pretty much exactly 20s for it to be anything else.

I wonder if 'fd_timeout' had been previously queued already with the 20s timeout, and not canceled. So then the new queuing of a 3-second timeout doesn't actually do anything, because the WORK_STRUCT_PENDING_BIT is still set.

So maybe we're missing a cancel somewhere.

What happens if you add a

        cancel_delayed_work(&fd_timeout);

to before the queue_delayed_work() in __reschedule_timeout()? Does that possibly make the delay really be 3 seconds?

Linus

Yes, it does...

[    0.718571] floppy0: reschedule timeout lock fdc
[    1.650956] Refined TSC clocksource calibration: 2698.760 MHz.
[    1.651109] Switching to clocksource tsc
[    3.724664] floppy0: reschedule timeout do wakeup
[    3.724815] floppy0: no floppy controllers found

index cce7df3..c8064e4 100644
@@ -678,6 +678,8 @@ static void __reschedule_timeout(int drive, const char *message)
 	} else
 		delay = UDP->timeout;
 
+	cancel_delayed_work(&fd_timeout);
+
 	queue_delayed_work(floppy_wq, &fd_timeout, delay);
 	if (UDP->flags & FD_DEBUG)
 		DPRINT("reschedule timeout %s\n", message);

Of course, a 3 second delay at this point in boot is still a fairly big bit of waiting, given how fast everything else is nowadays.

Calvin Walton <[email protected]>

Here's the patch I did for that yesterday

From: Andi Kleen <[email protected]>
Date: Mon, 2 Jul 2012 17:07:08 -0700
Subject: [PATCH] floppy: Run floppy initialization asynchronous

floppy_init is quite slow, 3s on my test system to determine that there is no floppy. Run it asynchronous to the other init calls to improve boot time.

Cuts down boot time by 1s on a system of mine.

index cce7df3..8b5769b 100644
@@ -191,6 +191,7 @@ static int print_unex = 1;
 #include <linux/mutex.h>
 #include <linux/io.h>
 #include <linux/uaccess.h>
+#include <linux/async.h>
 
 /*
  * PS/2 floppies have much slower step rates than regular floppies.

@@ -4122,7 +4123,7 @@ static struct kobject *floppy_find(dev_t dev, int *part, void *data)
 	return get_disk(disks[drive]);
 }
 
-static int __init floppy_init(void)
+static int __init do_floppy_init(void)
 {
 	int i, unit, drive;
 	int err, dr;

@@ -4337,6 +4338,24 @@ out_put_disk:
 	return err;
 }
 
+#ifndef MODULE
+static __init void floppy_async_init(void *data, async_cookie_t cookie)
+{
+	do_floppy_init();
+}
+#endif
+
+static int __init floppy_init(void)
+{
+#ifdef MODULE
+	return do_floppy_init(void);
+#else
+	/* Don't hold up the bootup by the floppy initialization */
+	async_schedule(floppy_async_init, NULL);
+	return 0;
+#endif
+}
+
 static const struct io_region {
 	int offset;
 	int size;

1.7.7.6

Ok. And I see the previous timeout - it's this:

        reschedule_timeout(MAXTIMEOUT, "floppy init");

that sets the fd_timeout to 20 seconds initially.

That whole fd_timeout code is broken, though. I'm not sure what the floppy init timeout is supposed to do, when the floppy reset code wants to re-use it.

And yes, the 3-second timeout is still too long.

Doing it asynchronously like Andi does helps a bit, but I suspect we could make the reset timeout shorter still just to make the initial "you don't have a floppy drive" code go faster.

That said, why even compile in the floppy driver any more? Even if you have the hardware, it probably doesn't work after ten years of gathering dust. Those floppy drives weren't exactly reliable even back in the days..

Anyway, I looked up the 82078 docs for reset. Holding the reset low *does* cause an interrupt, but I'm not finding how long the reset might take. But for the controller it really should be milliseconds, not seconds, I suspect. Can anybody find the appropriate reset timeout?

Linus

I think it would be more effective if the floppy driver initialized earlier, I think I have some slowdown because it starts too late.

I used to boot simulators from make fdimage some time ago. Until the kernels got too large :-)

But yes make isoimage is the way to go and

I'll remove it from my configs.

Thanks for the debugging.

-Andi

[email protected] -- Speaking for myself only

Still doesn't explain why reverting 070ad7e793dc6 (which made the whole thing completely serialized) doesn't fix it though; that's quite a mystery to me.

I will look into it once I am back again from vacation next week. In the meantime, I'd propose to simply add the cancel_delayed_work() for 3.5; it's an obvious bug I made during the timer -> workqueue conversion, as we used to do del_timer() before.

Jiri Kosina
SUSE Labs

Yes I do.

That works. Patch cuts it down to 3s as before

(and with the async probe patch I posted earlier the kernel boot time goes down by ~1s from 14 to 13ish)

-Andi

With Linus patch:

[    2.492449] calling  floppy_init+0x0/0xe46 @ 1
[    2.507259] floppy0: lock_fdc: -1 (out of 8)
[    2.507304] floppy0: __reschedule_timeout: setting timeout to 750
[    2.507330] floppy0: reschedule timeout lock fdc
[    5.509642] floppy0: reschedule timeout do wakeup
[    5.509683] floppy0: no floppy controllers found
[    5.509796] initcall floppy_init+0x0/0xe46 returned -19 after 2952148
usecs
[    5.509826] calling  brd_init+0x0/0x1ce @ 1

Ok, I committed it and pushed out.

That said, I'm surprised that you report that the revert doesn't work, though. Before commit 070ad7e793dc, there was a "del_timer()" there, and re-introducing that del_timer() (and canceling the work is the equivalent of that) should have taken care of the issue.

Odd, but I can't find it in myself to care too much.

Linus

Sorry for the delay. Here's the output on my system with floppy=debug and Linus' debug patch:

[    2.480521] calling  floppy_init+0x0/0xe46 @ 1
[    2.495325] floppy0: lock_fdc: -1 (out of 8)
[    2.495369] floppy0: reschedule timeout lock fdc
[   22.501736] floppy0: reschedule timeout do wakeup
[   22.501762] floppy0: no floppy controllers found
[   22.501896] initcall floppy_init+0x0/0xe46 returned -19 after

19588875 usecs

[email protected] -- Speaking for myself only.