Hello all,
I tried using a semi-recent (3.16.0-38-generic) live ISO session of MINT today,
but I noticed that my system completely hung at boot
(having booted via a hot reset of the machine).
Thus after a while, I decided to cold boot it instead (thinking
"WTF, hardware state must have been influenced by cosmic radiation").
Less surprisingly, it managed to hang again.
Thus I decided to keep waiting some more.
And finally (after several minutes) it reacted with message
EXT4-fs (sda2): recovery complete
dmesg timed trace:
[ 14.192858] [drm] Cannot find any crtc or sizes - going 1024x768
[ 14.219096] nouveau [ DRM] allocated 1024x768 fb: 0x70000, bo f6af2800
[ 14.222758] nouveau 0000:04:00.0: fb1: nouveaufb frame buffer device
[ 14.226297] [drm] Initialized nouveau 1.1.2 20120801 for 0000:04:00.0 on mino
r 1
[ 15.367568] sd 4:0:0:0: [sda] Attached SCSI removable disk
[ 16.967523] SGI XFS with ACLs, security attributes, realtime, large block/ino
de numbers, no debug enabled
[ 17.005616] JFS: nTxBlock = 8192, nTxLock = 65536
[ 18.127082] FAT-fs (sda1): Volume was not properly unmounted. Some data may b
e corrupt. Please run fsck.
[ 18.164828] EXT4-fs (sda2): mounting ext3 file system using the ext4 subsyste
m
[ 18.651731] random: nonblocking pool is initialized
[ 19.788049] ACPI Warning: \_SB_.PCI0.P0P4.GFX0._DSM: Argument #4 type mismatc
h - Found [Buffer], ACPI requires [Package] (20140424/nsarguments-95)
[ 19.790853] ACPI Warning: \_SB_.PCI0.P0P4.GFX0._DSM: Argument #4 type mismatc
h - Found [Buffer], ACPI requires [Package] (20140424/nsarguments-95)
[ 248.211176] EXT4-fs (sda2): recovery complete
[ 249.595977] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts:
(null)
(note the HUGE gap in dmesg timestamps above)
All that *may* have been acceptable, if it were not for the fact
that especially during boot
certain activity progress is not readily visible,
thus there's a *lot* of confusion of what is [not] happening with the system
(as strongly opposed to a situation where one is mounting an ext4 partition
directly via the shell, where it's quite obvious that mount is hanging
right at the shell prompt,
and diagnostic verification via dmesg etc. is readily reachable,
as opposed to system boot).
This issue likely is reproducible via the same live boot,
in combination with an ext4 partition (e.g. sitting on same boot block device)
which has been set up to need recovery.
Details (grub.conf setup etc.):
menuentry "Linux Mint 17.2 KDE 32-bit" {
set isofile="/boot/mint/linuxmint-17.2-kde-32bit.iso"
export isofile
set boottool="casper"
export boottool
set liveinitrd="/$boottool/initrd.lz"
export liveinitrd
loopback loop $isofile
set gfxpayload=keep
#linux (loop)/$boottool/vmlinuz file=/cdrom/preseed/linuxmint.seed boot=$boott
ool iso-scan/filename=${iso_path} config initrd=$liveinitrd live-media-path=/$bo
ottool debug nosplash fromiso=/dev/disk/by-label/amohr_iso2/$isofile --
linux (loop)/$boottool/vmlinuz file=/cdrom/preseed/linuxmint.seed boot=$bootto
ol iso-scan/filename=$isofile config initrd=$liveinitrd live-media-path=/$bootto
ol debug nosplash fromiso=/dev/disk/by-label/amohr_iso2/$isofile --
initrd (loop)$liveinitrd
#linux (loop)/casper/vmlinuz boot=casper quiet splash noeject noprompt fromiso
=/dev/disk/by-label/amohr_iso2/$isofile boot=live config live-media-path=/casper
--
#initrd (loop)/casper/initrd.lz
#linux (loop)/live/vmlinuz boot=live config initrd=/live/initrd.img live-media-path=/live debug nosplash fromiso=/dev/disk/by-label/amohr_iso2/$isofile --
#initrd (loop)/live/initrd.img
}
So, all in all it's just a pretty surprising situation
to have to wait for several minutes during boot
(with some other potentially confusing kernel messages
generated in the meantime),
and then finally surprisingly being greeted with a "recovery complete" message
despite never actually having been informed that ext4 mounting
*IS* in fact entering recovery
(or any other potentially longer-term activity during mounting)!!
So, plain cold usability-focussed judgment:
- mounting may hang for longer times, even during (potentially non-observable,
especially in GUI-only boot environment) boot,
without much indication of *both* state *and* progress
- progress may easily not be determinable via "out of band signalling" ;)
(completely silent USB stick rather than plain old metal platters HDD!!)
- ext4 mount log as of 3.16.0
does *not* have properly implemented "state progress"
when it comes to properly informing the user of what is happening
(namely, *enter*ing a longer-lasting recovery mode,
rather than merely having *finished* it)
Thus, the question here would be
which parts may need to be sufficiently improved
to achieve an acceptable level of usability.
I'd think that even simply adding a message
that one is about to enter a potentially longer-term operation
(with a details message such as "recovery")
rather than "standard" mount activity
would be sufficient,
both for text boot *and* GUI boot with some sufficiently accessible
"boot details" window.
Thanks,
Andreas Mohr
On Sun, Mar 20, 2016 at 06:10:53PM +0100, Andreas Mohr wrote:
> [ 18.164828] EXT4-fs (sda2): mounting ext3 file system using the ext4 subsyste
> [ 248.211176] EXT4-fs (sda2): recovery complete
> [ 249.595977] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts:
> (null)
>
> (note the HUGE gap in dmesg timestamps above)
>
> All that *may* have been acceptable, if it were not for the fact
> that especially during boot
> certain activity progress is not readily visible,
> thus there's a *lot* of confusion of what is [not] happening with the system
> (as strongly opposed to a situation where one is mounting an ext4 partition
> directly via the shell, where it's quite obvious that mount is hanging
> right at the shell prompt,
> and diagnostic verification via dmesg etc. is readily reachable,
> as opposed to system boot).
I'm curious --- what kind of removable USB drive is your sda drive?
Normally journal replay does *not* take nearly four minutes. It
usually only takes at most a few seconds --- which is why we've not
bothered to put in any kind of progress notification scheme. (Which
on most Linux distribution would be covered by some boot graphics
anyway, so it would be largely wasted.)
There *is* such a progress bar system for a file system consistency
check, which normally is what can take minutes.
> - progress may easily not be determinable via "out of band signalling" ;)
> (completely silent USB stick rather than plain old metal platters HDD!!)
Ah, it's some USB stick. I'm guessing it must be a *really* crappy
USB stick that doesn't do random writes well at all. Even so, though
this is quite unusual. This is much more normal:
[8583.604009] sd 9:0:0:0: [sdc] Attached SCSI removable disk
[8589.049603] EXT4-fs (sdc1): recovery complete
[8589.055767] EXT4-fs (sdc1): mounted filesystem with ordered data mode. Opts: (null)
This is with an amazingly craptastic 1GB USB stick drive made of
plastic which looks like it would fall apart if you twisted it
slightly as you insert or remove it, and for which I paid less than
$4.00 USD. (Basically something I treat as completely disposable. :-)
And as it turns out, most of this time is the delay between when the
kernel notified udevd, and when udisks actually got around to mounting
the device. After a clean unmount, where no recovery / journal replay
is needed:
[9108.564843] sd 15:0:0:0: [sdc] Attached SCSI removable disk
[9113.746002] EXT4-fs (sdc1): mounted filesystem with ordered data mode. Opts: (null)
> Thus, the question here would be
> which parts may need to be sufficiently improved
> to achieve an acceptable level of usability.
> I'd think that even simply adding a message
> that one is about to enter a potentially longer-term operation
> (with a details message such as "recovery")
> rather than "standard" mount activity
> would be sufficient,
> both for text boot *and* GUI boot with some sufficiently accessible
> "boot details" window.
Well, we could, but on most devices, it's largely wasted. Perhaps the
more interesting question is why is your USB stick so slow? Because
that's going to have a much larger usability issue for you...
Cheers,
- Ted
Hello,
On Sun, Mar 20, 2016 at 05:51:23PM -0400, Theodore Ts'o wrote:
> On Sun, Mar 20, 2016 at 06:10:53PM +0100, Andreas Mohr wrote:
> > [ 18.164828] EXT4-fs (sda2): mounting ext3 file system using the ext4 subsyste
> > [ 248.211176] EXT4-fs (sda2): recovery complete
> > [ 249.595977] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts:
> > (null)
> >
> > (note the HUGE gap in dmesg timestamps above)
> >
> > All that *may* have been acceptable, if it were not for the fact
> > that especially during boot
> > certain activity progress is not readily visible,
> > thus there's a *lot* of confusion of what is [not] happening with the system
> > (as strongly opposed to a situation where one is mounting an ext4 partition
> > directly via the shell, where it's quite obvious that mount is hanging
> > right at the shell prompt,
> > and diagnostic verification via dmesg etc. is readily reachable,
> > as opposed to system boot).
>
> I'm curious --- what kind of removable USB drive is your sda drive?
Bus 001 Device 002: ID 0951:1665 Kingston Technology
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 0 (Defined at Interface level)
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
idVendor 0x0951 Kingston Technology
idProduct 0x1665
bcdDevice 1.00
iManufacturer 1 Kingston
iProduct 2 DataTraveler 2.0
Case label: DTSE9 64GB
USB 2.0 stick on USB 2.0 port.
Both hdparm -i and hdparm -I did not work, interestingly:
# hdparm -i /dev/sda
/dev/sda:
SG_IO: bad/missing sense data, sb[]: 70 00 05 00 00 00 00 0a 00 00 00 00 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
HDIO_GET_IDENTITY failed: Invalid argument
# hdparm -I /dev/sda
/dev/sda:
SG_IO: bad/missing sense data, sb[]: 70 00 05 00 00 00 00 0a 00 00 00 00 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
ATA device, with non-removable media
Model Number: �H���H���H��H� �H�@�H�`�H���H���H
Serial Number: �`�I� �H���H��H� �H
Firmware Revision: �H���H��
Standards:
Likely used: 1
Configuration:
Logical max current
cylinders 0 0
heads 0 0
sectors/track 52736 0
--
bytes/track: 1021 bytes/sector: 0
Logical/Physical Sector size: 512 bytes
device size with M = 1024*1024: 0 MBytes
device size with M = 1000*1000: 0 MBytes
cache/buffer size = unknown
Capabilities:
IORDY not likely
Buffer type: 9340: dual port, multi-sector with read caching ability
Buffer size: 31396.0kB bytes avail on r/w long: 37728
Cannot perform double-word IO
R/W multiple sector transfer: not supported
DMA: not supported
PIO: pio0
(but these hdparm queries also fail when testing another USB stick -
on that machine at least,
so I'm not certain any more whether such behaviour is expected or not -
but I did sorta expect a plain IDENTIFY to work)
Just tested second USB stick on another machine - IDENTIFY failed, too
(also with sg_ident),
so that seems "normal" behaviour.
> Normally journal replay does *not* take nearly four minutes. It
> usually only takes at most a few seconds --- which is why we've not
> bothered to put in any kind of progress notification scheme. (Which
> on most Linux distribution would be covered by some boot graphics
> anyway, so it would be largely wasted.)
True, from recollection
for various devices
ext* recovery is a lot faster than a standard full fsck.
Makes it all the more mysterious why it now happened that way here.
> There *is* such a progress bar system for a file system consistency
> check, which normally is what can take minutes.
>
> > - progress may easily not be determinable via "out of band signalling" ;)
> > (completely silent USB stick rather than plain old metal platters HDD!!)
>
> Ah, it's some USB stick. I'm guessing it must be a *really* crappy
> USB stick that doesn't do random writes well at all. Even so, though
> this is quite unusual. This is much more normal:
>
> [8583.604009] sd 9:0:0:0: [sdc] Attached SCSI removable disk
> [8589.049603] EXT4-fs (sdc1): recovery complete
> [8589.055767] EXT4-fs (sdc1): mounted filesystem with ordered data mode. Opts: (null)
>
> This is with an amazingly craptastic 1GB USB stick drive made of
> plastic which looks like it would fall apart if you twisted it
> slightly as you insert or remove it, and for which I paid less than
> $4.00 USD. (Basically something I treat as completely disposable. :-)
Hmm, yeah, it might have started to happen now
since device seems to be more in use now
(read: pristine factory status now gone, thus all blocks used,
thus it now actively needs to do erase block processing,
and if that has annoying weaknesses, then......).
So yeah, that might hint at annoyingly strong weaknesses
(annoyingly weak strongness ;)
in flash management implementation.
bonnie++ -s512 -r256 -d bonnie_test
Writing a byte at a time...done
Writing intelligently...done
Rewriting...done
Reading a byte at a time...done
Reading intelligently...done
start 'em...done...done...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version 1.97 ------Sequential Output------ --Sequential Input- --Random-
Concurrency 1 -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP /sec %CP
mint 512M 110 72 5173 3 5721 1 704 98 +++++ +++ 91.0 1
Latency 6428ms 2545ms 2241ms 26638us 64us 7248us
Version 1.97 ------Sequential Create------ --------Random Create--------
mint -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
files /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP
16 1624 7 +++++ +++ 3263 11 3676 19 +++++ +++ 10935 49
Latency 1061us 1950us 1766us 555us 257us 993us
1.97,1.97,mint,1,1458889676,512M,,110,72,5173,3,5721,1,704,98,+++++,+++,91.0,1,16,,,,,1624,7,+++++,+++,3263,11,3676,19,+++++,+++,10935,49,6428ms,2545ms,2241ms,26638us,64us,7248us,1061us,1950us,1766us,555us,257us,993us
I haven't had the "opportunity" to do another reboot yet,
thus I couldn't check whether behaviour is now different.
> > Thus, the question here would be
> > which parts may need to be sufficiently improved
> > to achieve an acceptable level of usability.
> > I'd think that even simply adding a message
> > that one is about to enter a potentially longer-term operation
> > (with a details message such as "recovery")
> > rather than "standard" mount activity
> > would be sufficient,
> > both for text boot *and* GUI boot with some sufficiently accessible
> > "boot details" window.
>
> Well, we could, but on most devices, it's largely wasted. Perhaps the
> more interesting question is why is your USB stick so slow? Because
> that's going to have a much larger usability issue for you...
Hmm, ok, I guess I could accept
not having a pre-recovery announcement done
if recovery is fully intended to be rather fast always.
Still, in my case status reporting then ended up sufficiently irritating,
due to rather unexpected behaviour (probably of this stick).
> Cheers,
>
> - Ted
Thank you!
(and apologies for the large delay in replying)
Andreas Mohr
--
GNU/Linux. It's not the software that's free, it's you.