[opensuse] Kernel crash on multiple file write on reiserfs GPT partition.

23 May 2014

      Hi,

I am hitting a kernel crash and BUG when doing repeated file writes on a 
GPT partition, made as reiserfs.

The machine locks completely, even keyboard LEDs do not change state.

The code is this (trimmed for clarity):

         for Z in `seq 1 3000`;
 	do
 	  dd if=/dev/zero of=/mnt/test/fichero_$Z count=1 bs=1M conv=fdatasync >> logfile 2>&1.
         done

         ls -lh /mnt/test/* > /dev/null 2>&1.

         rm /mnt/test/fichero* 2>&1 |  tee -a some_log

What I see on screen is that it apparently writes the 3000 thousand files, 
deletes them (all the operations are timed), and then this, hand copied 
from a screen photo with camera:

*************************************
[62148.7840471] BUG: unable to handle kernel paging request at ffffc90019d54250
[62148.7840454] IP: [<ffffffff8105e7a9>] get_next_timer_interrupt+0xa9/0x270
[62148.7840456] PGD 23f027067 PUD 23f028067 PMD 19b255067 PTE 0
[62148.7840457] Oops: 0000 [#1] PREEMPT SMP
*************************************

I will post the photo later.

(it is not fully clear what are '8' or '0')

The crash does not happen if I remove the "conv=fdatasync" from the 'dd' 
line.

What I see on the "logfile" is (last lines):

+++,,,,,,,,,,,,,,,,,,,,,,,,,,
1048576 bytes (1.0 MB) copied, 0.040832 s, 25.7 MB/s
1+0 records in
1+0 records out
1048576 bytes (1.0 MB) copied, 0.0407661 s, 25.7 MB/s
1+0 records in
1+0 records out
1048576 bytes (1.0 MB) copied, 0.0575303 s, 18.2 MB/s
......................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
 ............................................................................................................................
,,,,,,,,,,,,,,,,,,,,,,,,,,++-

What I see on the "some_log" is (last lines):

+++,,,,,,,,,,,,,,,,,,,,,,,,,,
---------------------------------------------------------------
**** Prueba escritura miles ficheros pequeños en la particion 16
**** Inicio a 2014-05-23 05:50:33.701240101+02:00

====   Escritos 3000 ficheros en 141 segundos (Part 16)

    Listando particion 16
====   Listados 3000 ficheros en 0 segundos (Part 16)

    Borrando 3000 ficheros
====   Borrados 3000 ficheros en 2 segundos (Part 16)

**** Fin a 2014-05-23 05:52:56.309504061+02:00

---------------------------------------------------------------
**** Prueba escritura miles ficheros pequeños en la particion 17
**** Inicio a 2014-05-23 05:52:56.404005507+02:00
,,,,,,,,,,,,,,,,,,,,,,,,,,++-

It appears that the last entries on the logs get corrupted, and do not 
match completely what gets displayed on the screen.

What I see on /var/log/messages is:

+++,,,,,,,,,,,,,,,,,,,,,,,,,,
<0.5> 2014-05-23 05:50:33 Telcontar kernel - - - [61860.598210] REISERFS (device sde16): found reiserfs format "3.6" with standard journal
<0.5> 2014-05-23 05:50:33 Telcontar kernel - - - [61860.598218] REISERFS (device sde16): using ordered data mode
<0.4> 2014-05-23 05:50:33 Telcontar kernel - - - [61860.598220] reiserfs: using flush barriers
<0.5> 2014-05-23 05:50:33 Telcontar kernel - - - [61860.622403] REISERFS (device sde16): journal params: device sde16, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
<0.5> 2014-05-23 05:50:33 Telcontar kernel - - - [61860.622712] REISERFS (device sde16): checking transaction log (sde16)
<0.5> 2014-05-23 05:50:33 Telcontar kernel - - - [61860.643359] REISERFS (device sde16): Using r5 hash to sort names
<0.5> 2014-05-23 05:52:56 Telcontar kernel - - - [62003.293181] REISERFS (device sde17): found reiserfs format "3.6" with standard journal
<0.5> 2014-05-23 05:52:56 Telcontar kernel - - - [62003.293189] REISERFS (device sde17): using ordered data mode
<0.4> 2014-05-23 05:52:56 Telcontar kernel - - - [62003.293191] reiserfs: using flush barriers
<0.5> 2014-05-23 05:52:56 Telcontar kernel - - - [62003.315677] REISERFS (device sde17): journal params: device sde17, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
<0.5> 2014-05-23 05:52:56 Telcontar kernel - - - [62003.315994] REISERFS (device sde17): checking transaction log (sde17)
<0.5> 2014-05-23 05:52:56 Telcontar kernel - - - [62003.339970] REISERFS (device sde17): Using r5 hash to sort names
<3.6> 2014-05-23 05:53:01 Telcontar systemd 1 - -  Starting Session 471 of user news.
......................................................................................2014-05-23 10:00:43+02:00 - Booting the system now  ================================================================================ 
Linux Telcontar 3.11.10-11-desktop #1 SMP PREEMPT Mon May 12 13:37:06 UTC 2014 (3d22b5f) x86_64 x86_64 x86_64 GNU/Linux
<0.6> 2014-05-23 10:00:45 Telcontar kernel - - - [    0.000000] Initializing cgroup subsys cpuset
,,,,,,,,,,,,,,,,,,,,,,,,,,++-

The detail about "Starting Session 471 of user news" may be important. It 
is a cronjob that starts leafnode nntp fetch, and the partition dedicated 
to news storage is a reiserfs one. I had the crash happen several times 
precisely at that point, but not all, apparently.

There is also some corruption in the log file of the fetchnews run, 
although the job itself succeeds:

+++,,,,,,,,,,,,,,,,,,,,,,,,,,
================> 2014-05-23 05:53:01.738753848+02:00   Start fetchnews 
session

WARNING:  Make sure that syslog.conf captures news.debug logging
--------  and obtain your debug output from syslog.
WARNING:  The screen output below is not sufficient. Check syslog!

leafnode 1.11.10: verbosity level is 1, debugmode is 1
try_lock(timeout=5), fqdn="Telcontar.valinor"
nntp.opensuse.org: connecting to port nntp...
nntp.opensuse.org: connected to 130.57.2.16:119, reply: 200
nntp.opensuse.org: connected.
nntp.opensuse.org: using STAT <message-ID> command.
nntp.opensuse.org: 0 articles posted.
nntp.opensuse.org: getting new newsgroups
nntp.opensuse.org: got 0 new newsgroups.
nntp.opensuse.org: conversation completed, disconnected.
nntp.novell.com: connecting to port nntp...
nntp.novell.com: connected to 130.57.2.15:119, reply: 200
nntp.novell.com: connected.
nntp.novell.com: using STAT <message-ID> command.
nntp.novell.com: 0 articles posted.
nntp.novell.com: getting new newsgroups
nntp.novell.com: got 0 new newsgroups.
nntp.novell.com: conversation completed, disconnected.
wrote active file with 342 lines
Started process to update overview data in the background.
Network activity has finished.
================> 2014-05-23 05:53:22.127932178+02:00   End fetchnews session
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@================> 2014-05-23 10:03:01.349875385+02:00   Start fetchnews session
,,,,,,,,,,,,,,,,,,,,,,,,,,++-

But it finished correctly before the crash, it is only the log (on an ext4 
partition) that gets corrupted (the "^@^@^" chars)

+++,,,,,,,,,,,,,,,,,,,,,,,,,,
<7.7> 2014-05-23 05:53:22 Telcontar fetchnews 22699 - -  <211 3064 2 3083 opensuse.org.help.virtualization
<7.6> 2014-05-23 05:53:22 Telcontar fetchnews 22699 - -  opensuse.org.help.virtualization: no new articles
<7.7> 2014-05-23 05:53:22 Telcontar fetchnews 22699 - -  >QUIT
<7.6> 2014-05-23 05:53:22 Telcontar fetchnews 22699 - -  wrote active file with 342 lines
<7.7> 2014-05-23 05:53:22 Telcontar fetchnews 23145 - -  Process forked.
<7.6> 2014-05-23 05:53:22 Telcontar fetchnews 22699 - -  child has process ID 23145
<7.7> 2014-05-23 05:53:22 Telcontar fetchnews 23145 - -  Process done.
<7.7> 2014-05-23 10:03:01 Telcontar fetchnews 4153 - -  config: debugmode is 1
<7.7> 2014-05-23 10:03:01 Telcontar fetchnews 4153 - -  config: maxage is 0
,,,,,,,,,,,,,,,,,,,,,,,,,,++-

The code I'm running is a script, that I can post later if wanted, that 
does a sequence of tests on a 3TB hard disk with 19 GPT partitions:

  formats all partitions
  repeat 3 times
    run hdparm -tT on all partitions
    creates and deletes 3 * 4G files on all partitions
    creates and deletes 3000 * 1M files on all partitions

This is done for xfs, ext4, btrfs, and reiserfs. It only crashes on 
reiserfs, randomly, on the small file test, on a different partition each 
time, and on any of the 3 runs.

I will now repeat the test with reiserfs only, leaving active tty10, in 
the hope of capturing the complete Oops text.

-- 
Cheers
        Carlos E. R.

        (from 13.1 x86_64 "Bottle" at Telcontar)

Carlos E. R.

Andrey Borzenkov

Carlos E. R.

Cristian Rodríguez

Carlos E. R.

auxsvr＠gmail.com

Carlos E. R.

auxsvr＠gmail.com

Carlos E. R.

Cristian Rodríguez

Carlos E. R.

Cristian Rodríguez

Carlos E. R.

Cristian Rodríguez

Carlos E. R.

Carlos E. R.

Carlos E. R.

Carlos E. R.

Cristian Rodríguez

Carlos E. R.

Carlos E. R.

Carlos E. R.

Andrey Borzenkov

Carlos E. R.

tags

participants (6)