INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

2 messages, 2 authors, 2008-07-21 · open the first message on its own page

INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Mr. James W. Laferriere <hidden>
Date: 2008-07-21 17:40:23

  	Hello All ,  forwarded because last post failed to appear ,  probably 
due to size limits .  This is an -edited- verion of the original .
  		Tia ,  JimL

-- 
+------------------------------------------------------------------+
| James   W.   Laferriere | System    Techniques | Give me VMS     |
| Network&System Engineer | 2133    McCullam Ave |  Give me Linux  |
| babydr@baby-dragons.com | Fairbanks, AK. 99701 |   only  on  AXP |
+------------------------------------------------------------------+

---------- Forwarded message ----------
Date: Sun, 20 Jul 2008 17:08:00 -0800 (AKDT)
From: Mr. James W. Laferriere <redacted>
To: linux-raid maillist <redacted>
Subject: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces
       ...

  	Hello All ,
  	All 5 processes are un-killable (kill -9) totally unresponsive to the 
kill command .  The system is still (so far) responsive to ssh sessions & on 
serial console which is still logging all this .
  	Sorry about the verbosity & (possible) duplicated information .
  	Any data I can get I'll try acquiring ,  but request should probably be 
rather quick in coming as the 'Call traces' keep arriving ~ 30 Seconds .
  		Tia ,  JimL

  	Running the following .sh file .
<bonniemd3.sh> N=5
/root/bonnie++-1.03c/bonnie++ -u0:0 -p${N}

    SIZE="`echo -en "scale=0\n((717698048-4096)/((1024^2)*${N}))*1024\nquit\n" | 
bc`k"
    echo "\${SIZE}=${SIZE}"

# Note: add or subtract a line of the below for ${N} > 5 or ${N} < 5

    time /root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s ${SIZE} -f -y &
    time /root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s ${SIZE} -f -y &
    time /root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s ${SIZE} -f -y &
    time /root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s ${SIZE} -f -y &
    time /root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s ${SIZE} -f -y &
</bonniemd3.sh>

   00:39:06 up  2:30,  2 users,  load average: 7.00, 7.00, 6.93


root      3873  9.1  0.0      0     0 ?        S<   Jul20  12:43 [md3_raid5]
root      3978  9.1  0.0   2792  1100 pts/0    D    Jul20   8:38 
/root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s 139264k -f -y
root      3980  9.1  0.0   2792  1096 pts/0    D    Jul20   8:36 
/root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s 139264k -f -y
root      3982  9.1  0.0   2792  1100 pts/0    D    Jul20   8:35 
/root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s 139264k -f -y
root      3983  9.1  0.0   2792  1100 pts/0    D    Jul20   8:39 
/root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s 139264k -f -y
root      3985  9.1  0.0   2792  1100 pts/0    D    Jul20   8:34 
/root/bonnie++-1.03c/bonnie++ -u 0:0 -y -d /md3 -x 15 -s 139264k -f -y

-rw-------  1 root root 1073741824 2008-07-20 23:39:42.905421676 +0000 
Bonnie.3985.030
-rw-------  1 root root 1073741824 2008-07-20 23:40:14.815422649 +0000 
Bonnie.3983.031
-rw-------  1 root root 1073741824 2008-07-20 23:40:23.435422370 +0000 
Bonnie.3978.031
-rw-------  1 root root 1073741824 2008-07-20 23:40:35.065423200 +0000 
Bonnie.3980.031
-rw-------  1 root root 1073741824 2008-07-20 23:40:37.785422947 +0000 
Bonnie.3982.031
-rw-------  1 root root 1073741824 2008-07-20 23:40:51.085422242 +0000 
Bonnie.3985.031
-rw-------  1 root root 1012187136 2008-07-20 23:41:20.305423802 +0000 
Bonnie.3983.032
-rw-------  1 root root  747651072 2008-07-20 23:41:20.515422821 +0000 
Bonnie.3980.032
-rw-------  1 root root  423944192 2008-07-20 23:41:20.545422363 +0000 
Bonnie.3985.032
-rw-------  1 root root  897753088 2008-07-20 23:41:20.545422363 +0000 
Bonnie.3978.032
-rw-------  1 root root  624009216 2008-07-20 23:41:20.565423044 +0000 
Bonnie.3982.032

Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/md10             33224296  18792924  12716440  60% /
/dev/md11               248783     61029    174910  26% /boot
/dev/md3             717698048 171397224 546300824  24% /md3


   root@filesrv2:~ # mdadm -D /dev/md3
mdadm: metadata format 00.90 unknown, ignored.
mdadm: metadata format 00.90 unknown, ignored.
mdadm: metadata format 00.90 unknown, ignored.
/dev/md3:
          Version : 00.90
    Creation Time : Mon Jul  7 21:42:12 2008
       Raid Level : raid6
       Array Size : 717829120 (684.58 GiB 735.06 GB)
    Used Dev Size : 143565824 (136.92 GiB 147.01 GB)
     Raid Devices : 7
    Total Devices : 8
Preferred Minor : 3
      Persistence : Superblock is persistent

    Intent Bitmap : Internal

      Update Time : Sun Jul 20 23:04:51 2008
            State : active
   Active Devices : 7
Working Devices : 8
   Failed Devices : 0
    Spare Devices : 1

       Chunk Size : 1024K

             UUID : 7617aeb3:65870440:a619e7ca:f8a16963
           Events : 0.7

      Number   Major   Minor   RaidDevice State
         0       8       32        0      active sync   /dev/sdc
         1       8       48        1      active sync   /dev/sdd
         2       8       64        2      active sync   /dev/sde
         3       8       80        3      active sync   /dev/sdf
         4       8       96        4      active sync   /dev/sdg
         5       8      112        5      active sync   /dev/sdh
         6       8      128        6      active sync   /dev/sdi

         7       8      144        -      spare   /dev/sdj



e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex, Flow 
Control: RX/TX
bonnie++ used greatest stack depth: 5000 bytes left
md: md3 stopped.
md: bind<sdd>
md: bind<sde>
md: bind<sdf>
md: bind<sdg>
md: bind<sdh>
md: bind<sdi>
md: bind<sdj>
md: bind<sdc>
raid5: device sdc operational as raid disk 0
raid5: device sdi operational as raid disk 6
raid5: device sdh operational as raid disk 5
raid5: device sdg operational as raid disk 4
raid5: device sdf operational as raid disk 3
raid5: device sde operational as raid disk 2
raid5: device sdd operational as raid disk 1
raid5: allocated 7340kB for md3
raid5: raid level 6 set md3 active with 7 out of 7 devices, algorithm 2
RAID5 conf printout:
   --- rd:7 wd:7
   disk 0, o:1, dev:sdc
   disk 1, o:1, dev:sdd
   disk 2, o:1, dev:sde
   disk 3, o:1, dev:sdf
   disk 4, o:1, dev:sdg
   disk 5, o:1, dev:sdh
   disk 6, o:1, dev:sdi
md3: bitmap initialized from disk: read 9/9 pages, set 2 bits
created bitmap (137 pages) for device md3
Filesystem "md3": Disabling barriers, not supported by the underlying device
XFS mounting filesystem md3
Ending clean XFS mount for filesystem: md3
INFO: task pdflush:393 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D c8209f80  4748   393      2
         f75e5e58 00000046 f7f7ad50 c8209f80 f7f7a8a0 f75e5e24 c014fc57 00000000
         f7f7a8a0 e5d0dd00 c8209f80 f75e4000 c0819e00 c8209f80 f7f7aaf4 f75e5e44
         00000286 f75e5e80 f510de30 f75e5e58 c0142233 f510de00 f75e5e80 f510de30
Call Trace:
   [<c014fc57>] ? mark_held_locks+0x67/0x80
   [<c0142233>] ? add_wait_queue+0x33/0x50
   [<c03a7f85>] xfs_buf_wait_unpin+0xb5/0xe0
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c0127a60>] ? default_wake_function+0x0/0x10
   [<c03a84fb>] xfs_buf_iorequest+0x4b/0x80
   [<c03adeee>] xfs_bdstrat_cb+0x3e/0x50
   [<c03a495c>] xfs_bwrite+0x5c/0xe0
   [<c039e941>] xfs_syncsub+0x121/0x2b0
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c018a43b>] ? lock_super+0x1b/0x20
   [<c039e1d8>] xfs_sync+0x48/0x70
   [<c03af833>] xfs_fs_write_super+0x23/0x30
   [<c018a80f>] sync_supers+0xaf/0xc0
   [<c0169259>] wb_kupdate+0x29/0x100
   [<c016a0cc>] ? __pdflush+0xcc/0x1a0
   [<c016a0d2>] __pdflush+0xd2/0x1a0
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c016a1d1>] pdflush+0x31/0x40
   [<c0169230>] ? wb_kupdate+0x0/0x100
   [<c016a1a0>] ? pdflush+0x0/0x40
   [<c0141e2c>] kthread+0x5c/0xa0
   [<c0141dd0>] ? kthread+0x0/0xa0
   [<c0103d67>] kernel_thread_helper+0x7/0x10
   =======================
2 locks held by pdflush/393:
   #0:  (&type->s_umount_key#17){----}, at: [<c018a7b2>] sync_supers+0x52/0xc0
   #1:  (&type->s_lock_key#7){--..}, at: [<c018a43b>] lock_super+0x1b/0x20

    ...snip... Repeats of above message ad-infintum .

   root@filesrv2:~ #


-- 
+------------------------------------------------------------------+
| James   W.   Laferriere | System    Techniques | Give me VMS     |
| Network&System Engineer | 2133    McCullam Ave |  Give me Linux  |
| babydr@baby-dragons.com | Fairbanks, AK. 99701 |   only  on  AXP |
+------------------------------------------------------------------+

Re: INFO: task pdflush:393 blocked for more than 120 seconds. & Call traces ... (fwd)

From: Randy Dunlap <hidden>
Date: 2008-07-21 18:21:15

[cc-ing lkml]


On Mon, 21 Jul 2008 09:40:23 -0800 (AKDT) Mr. James W. Laferriere wrote:

<http://marc.info/?l=linux-raid&m=121666205220699&w=2>


Basically a "me too", on x86_64, 4 proc, 8 GB RAM.

I'm using OLTEST (Oracle Linux test) instead of bonnie.  OLTEST never
finishes because of this.

kernel log (12 MB) is here: http://oss.oracle.com/~rdunlap/kerneltest/logs/netcon-4655.log


---
~Randy
Linux Plumbers Conference, 17-19 September 2008, Portland, Oregon USA
http://linuxplumbersconf.org/
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help