[Gluster-devel] Bonnie++ bailing out
KwangErn Liew
ke.liew at gmail.com
Sat Sep 13 08:30:59 UTC 2008
Hi,
I've been running bonnie++ 1.03a more than 24hrs ago, and only recently it
has failed. It is an AFR setup.
$ bonnie++ -u bonnie -d /home/storage -s 7904m:256k -n 1024:-2:5m:30 -x 10
Using uid:100, gid:65534.
name,file_size,putc,putc_cpu,put_block,put_block_cpu,rewrite,rewrite_cpu,getc,getc_cpu,get_block,get_block_cpu,seeks,seeks_cpu,num_files,seq_create,seq_create_cpu,seq_stat,seq_stat_cpu,seq_del,seq_del_cpu,ran_create,ran_create_cpu,ran_stat,ran_stat_cpu,ran_del,ran_del_cpu
Writing with putc()...Can't putc() - disk full?
Space is never a problem.
$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/hdv1 922G 11G 911G 2% /
Here are the GlusterFS 1.4.0-pre5 logs: (can't paste everything, so only the
relevant bits)
===== Client =====
2008-09-13 07:14:50 D [fuse-bridge.c:1510:fuse_writev_cbk] glusterfs-fuse:
445455: WRITE => 4096/4096,750338048/750342144
2008-09-13 07:14:50 D [fuse-bridge.c:1548:fuse_write] glusterfs-fuse:
445456: WRITE (0x515690, size=4096, offset=750342144)
2008-09-13 07:15:14 D [fuse-bridge.c:1510:fuse_writev_cbk] glusterfs-fuse:
445456: WRITE => 4096/4096,750342144/750346240
2008-09-13 07:15:14 D [fuse-bridge.c:1548:fuse_write] glusterfs-fuse:
445457: WRITE (0x515690, size=4096, offset=750346240)
2008-09-13 07:15:53 E [client-protocol.c:216:call_bail] gfs-client1:
activating bail-out. pending frames = 1. last sent = 2008-09-13 07:15:14.
last received = 2008-09-13 07:15:14. transport-timeout = 30
2008-09-13 07:15:53 C [client-protocol.c:223:call_bail] gfs-client1: bailing
transport
2008-09-13 07:15:53 D [socket.c:183:__socket_disconnect] gfs-client1:
shutdown() returned 0. setting connection state to -1
2008-09-13 07:15:53 W [socket.c:93:__socket_rwv] gfs-client1: EOF from peer
62.212.91.119:37268
2008-09-13 07:15:53 D [socket.c:568:socket_proto_state_machine] gfs-client1:
socket read failed (Transport endpoint is not connected) in state 1 (
62.212.91.119:37268)
2008-09-13 07:15:53 D [client-protocol.c:4153:protocol_client_cleanup]
gfs-client1: cleaning up state in transport object 0x50dd30
2008-09-13 07:15:53 E [client-protocol.c:4205:protocol_client_cleanup]
gfs-client1: forced unwinding frame type(1) op(WRITE) reply=@0x2aaaaae00940
2008-09-13 07:15:53 E [afr.c:2651:afr_writev_cbk] gfs-afr:
(path=/Bonnie.12457.001 child=gfs-client1) op_ret=-1 op_errno=107(Transport
endpoint is not connected)
2008-09-13 07:15:53 E [fuse-bridge.c:1516:fuse_writev_cbk] glusterfs-fuse:
445457: WRITE => -1 (Transport endpoint is not connected)
2008-09-13 07:15:53 D [afr.c:6333:notify] gfs-afr: GF_EVENT_CHILD_DOWN from
gfs-client1
2008-09-13 07:15:53 D [fuse-bridge.c:1548:fuse_write] glusterfs-fuse:
445458: WRITE (0x515c90, size=4096, offset=1073737728)
2008-09-13 07:15:53 E [afr.c:2651:afr_writev_cbk] gfs-afr:
(path=/Bonnie.12457.000 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2651:afr_writev_cbk] gfs-afr:
(path=/Bonnie.12457.000 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:1516:fuse_writev_cbk] glusterfs-fuse:
445458: WRITE => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445459: FLUSH 0x515c90
2008-09-13 07:15:53 E [afr.c:2974:afr_flush] gfs-afr: afrfdp->fdstate[] is
0, returning ENOTCONN
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445459: FLUSH() ERR => -1 (Transport endpoint is not connected)
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445460: CLOSE 0x515c90
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445461: FLUSH 0x515690
2008-09-13 07:15:53 E [afr.c:2974:afr_flush] gfs-afr: afrfdp->fdstate[] is
0, returning ENOTCONN
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445461: FLUSH() ERR => -1 (Transport endpoint is not connected)
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445462: CLOSE 0x515690
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445463: FLUSH 0x5151b0
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.002 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.002 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445463: FLUSH() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:937:afr_incver_internal_lock_cbk] gfs-afr:
(path=/Bonnie.12457.000) none of the subvols are up for locking
2008-09-13 07:15:53 E [afr.c:940:afr_incver_internal_lock_cbk] gfs-afr:
afrfdp is NULL, for /Bonnie.12457.000
2008-09-13 07:15:53 E [afr.c:937:afr_incver_internal_lock_cbk] gfs-afr:
(path=/Bonnie.12457.001) none of the subvols are up for locking
2008-09-13 07:15:53 E [afr.c:940:afr_incver_internal_lock_cbk] gfs-afr:
afrfdp is NULL, for /Bonnie.12457.001
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.000 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.000 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445460: CLOSE() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] fuse/inode:
passivating inode(2013354535) lru=1/0 active=8 purge=20
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.001 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.001 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445462: CLOSE() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] fuse/inode:
passivating inode(2013354536) lru=2/0 active=7 purge=20
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445464: CLOSE 0x5151b0
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445465: FLUSH 0x516760
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.003 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.003 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445465: FLUSH() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445466: CLOSE 0x516760
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445467: FLUSH 0x517260
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.004 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.004 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445467: FLUSH() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.002 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.002 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445464: CLOSE() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] fuse/inode:
passivating inode(2013354537) lru=3/0 active=6 purge=20
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445468: CLOSE 0x517260
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445469: FLUSH 0x518140
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.005 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.005 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445469: FLUSH() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.003 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.003 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445466: CLOSE() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] fuse/inode:
passivating inode(2013354538) lru=4/0 active=5 purge=20
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445470: CLOSE 0x518140
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445471: FLUSH 0x5188b0
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.006 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.006 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445471: FLUSH() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.004 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.004 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445468: CLOSE() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] fuse/inode:
passivating inode(2013354539) lru=5/0 active=4 purge=20
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445472: CLOSE 0x5188b0
2008-09-13 07:15:53 D [fuse-bridge.c:1572:fuse_flush] glusterfs-fuse:
445473: FLUSH 0x519040
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.007 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:2919:afr_flush_cbk] gfs-afr:
(path=/Bonnie.12457.007 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445473: FLUSH() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.005 child=gfs-client1) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [afr.c:3012:afr_close_cbk] gfs-afr:
(path=/Bonnie.12457.005 child=gfs-client2) op_ret=-1 op_errno=77(File
descriptor in bad state)
2008-09-13 07:15:53 E [fuse-bridge.c:873:fuse_err_cbk] glusterfs-fuse:
445470: CLOSE() ERR => -1 (File descriptor in bad state)
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] fuse/inode:
passivating inode(2013354540) lru=6/0 active=3 purge=20
2008-09-13 07:15:53 D [fuse-bridge.c:1599:fuse_release] glusterfs-fuse:
445474: CLOSE 0x519040
2008-09-13 07:15:53 D [inode.c:268:__inode_activate] fuse/inode: activating
inode(2013354535),
... (continues...)
===== Server ======
2008-09-13 07:02:05 D [socket.c:636:socket_proto_state_machine] gfs-server2:
partial header read on NB socket. continue later
2008-09-13 07:02:26 D [socket.c:636:socket_proto_state_machine] gfs-server2:
partial header read on NB socket. continue later
2008-09-13 07:02:26 D [socket.c:636:socket_proto_state_machine] gfs-server2:
partial header read on NB socket. continue later
2008-09-13 07:02:33 D [socket.c:636:socket_proto_state_machine] gfs-server2:
partial header read on NB socket. continue later
2008-09-13 07:02:57 W [socket.c:93:__socket_rwv] gfs-server2: EOF from peer
62.212.91.118:1022
2008-09-13 07:02:57 D [socket.c:568:socket_proto_state_machine] gfs-server2:
socket read failed (Transport endpoint is not connected) in state 1 (
62.212.91.118:1022)
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077150) lru=3/1024 active=8 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077151) lru=4/1024 active=7 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077152) lru=5/1024 active=6 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077153) lru=6/1024 active=5 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077154) lru=7/1024 active=4 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077155) lru=8/1024 active=3 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077156) lru=9/1024 active=2 purge=20
2008-09-13 07:02:57 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077157) lru=10/1024 active=1 purge=20
2008-09-13 07:02:57 D [server-protocol.c:6182:server_protocol_cleanup]
gfs-server2: cleaned up transport state for client 62.212.91.118:1022
2008-09-13 07:02:57 D [socket.c:1287:fini] gfs-server2: transport 0x50d980
destroyed
2008-09-13 07:02:57 D [addr.c:166:gf_auth] gfs-storage2: allowed = "*",
received addr = "62.212.91.118"
2008-09-13 07:02:57 D [server-protocol.c:5544:mop_setvolume] gfs-server2:
accepted client from 62.212.91.118:1022
2008-09-13 07:15:53 D [inode.c:268:__inode_activate] gfs-storage2/inode:
activating inode(1879077150), lru=9/1024 active=2 purge=20
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077150) lru=10/1024 active=1 purge=20
2008-09-13 07:15:53 D [inode.c:268:__inode_activate] gfs-storage2/inode:
activating inode(1879077150), lru=9/1024 active=2 purge=20
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077150) lru=10/1024 active=1 purge=20
2008-09-13 07:15:53 D [inode.c:268:__inode_activate] gfs-storage2/inode:
activating inode(1879077150), lru=9/1024 active=2 purge=20
2008-09-13 07:15:53 D [inode.c:311:__inode_retire] gfs-storage2/inode:
retiring inode(1879077150) lru=9/1024 active=1 purge=21
2008-09-13 07:15:53 D [inode.c:251:__inode_destroy] gfs-storage2/inode:
destroy inode(1879077150) [@0x50f7d0]
2008-09-13 07:15:53 D [inode.c:268:__inode_activate] gfs-storage2/inode:
activating inode(1879077151), lru=8/1024 active=2 purge=21
2008-09-13 07:15:53 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077151) lru=9/1024 active=1 purge=21
2008-09-13 07:15:54 D [inode.c:268:__inode_activate] gfs-storage2/inode:
activating inode(1879077151), lru=8/1024 active=2 purge=21
2008-09-13 07:15:54 D [inode.c:287:__inode_passivate] gfs-storage2/inode:
passivating inode(1879077151) lru=9/1024 active=1 purge=21
2008-09-13 07:15:54 D [inode.c:268:__inode_activate] gfs-storage2/inode:
activating inode(1879077151), lru=8/1024 active=2 purge=21
2008-09-13 07:15:54 D [inode.c:311:__inode_retire] gfs-storage2/inode:
retiring inode(1879077151) lru=8/1024 active=1 purge=22
2008-09-13 07:15:54 D [inode.c:251:__inode_destroy] gfs-storage2/inode:
destroy inode(1879077151) [@0x50ee30]
...(continues...)
Any clues?
KwangErn
More information about the Gluster-devel
mailing list