xfs
[Top] [All Lists]

Re: Still seeing hangs in xlog_grant_log_space

To: Dave Chinner <david@xxxxxxxxxxxxx>
Subject: Re: Still seeing hangs in xlog_grant_log_space
From: Mark Tinguely <tinguely@xxxxxxx>
Date: Wed, 09 May 2012 16:07:52 -0500
Cc: Juerg Haefliger <juergh@xxxxxxxxx>, xfs@xxxxxxxxxxx
In-reply-to: <20120509073507.GQ5091@dastard>
References: <20120425223845.GX9541@dastard> <CADLDEKvYkpUnMrqdMyqCmsYrZcUtiJ6ZRhrRu_ERTjn=r7M3Pg@xxxxxxxxxxxxxx> <20120426224412.GA9541@dastard> <CADLDEKs6oMDA-6OhmcFxyRoBVpduKtSput=53TQGn9NCAOXC1Q@xxxxxxxxxxxxxx> <20120426230738.GB9541@dastard> <CADLDEKuKLeYiqhQW0E9g_bS0VXoxPGPOck3N004Pxg4_Opbzow@xxxxxxxxxxxxxx> <20120427110922.GF9541@dastard> <CADLDEKtUHAGcOPT1jtcvyJVk+zsoL5_thYFtHJYs+w=6EGuVSA@xxxxxxxxxxxxxx> <CADLDEKs4YbNzj2c0HKHwSdUfKy0efdQRe1rOsWDkWUgd+BOGHw@xxxxxxxxxxxxxx> <20120507225944.GA5091@dastard> <20120509073507.GQ5091@dastard>
User-agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:9.0) Gecko/20120122 Thunderbird/9.0
On 05/09/12 02:35, Dave Chinner wrote:


Transaction      Wait queues     Grant head      Write Head      Log head       
 Log tail
-----------------------------------------------------------------------------------------
INACTIVE         empty empty     118 438024      118 438024      118 802        
 118 697
INACTIVE         empty empty     119 20240       119 20240       118 802        
 118 697
REMOVE           empty empty     118 438456      118 438456      118 802        
 118 697
REMOVE           empty empty     118 438772      118 438772      118 802        
 118 697
CREATE           empty empty     119 35872       119 35872       118 802        
 118 697
FSYNC_TS         active empty    119 205428      119 205428      118 802        
 118 697
FSYNC_TS         active empty    119 202944      119 202944      118 802        
 118 697
FSYNC_TS         active empty    119 200664      119 200664      118 802        
 118 697
REMOVE           empty empty     118 380316      118 380316      118 724        
 118 652
INACTIVE         empty empty     118 552532      118 552532      118 724        
 118 652
FSYNC_TS         empty empty     118 382140      118 382140      118 724        
 118 652
INACTIVE         empty empty     118 565968      118 565968      118 724        
 118 652
REMOVE           empty empty     119 25404       119 25404       118 802        
 118 697
INACTIVE         active empty    119 25580       119 25580       118 802        
 118 697



Just so you don't go down a blind alley, the timestamp on the log went backwards there. If you resort on the time stamps this does not go backwards.

Not sorted:
grep ungrant_exit trace* | awk '{print $3, $8, $20, $22, $24, $26, $28, $30, $32, $34, $36, $38}' | less

3501.000611: FSYNC_TS active empty 119 205428 119 205428 118 802 118 697
3501.004513: FSYNC_TS active empty 119 202944 119 202944 118 802 118 697
3501.005210: FSYNC_TS active empty 119 200664 119 200664 118 802 118 697
3500.962328: REMOVE empty empty 118 380316 118 380316 118 724 118 652
3500.962458: INACTIVE empty empty 118 552532 118 552532 118 724 118 652
3500.962770: FSYNC_TS empty empty 118 382140 118 382140 118 724 118 652
3500.964781: INACTIVE empty empty 118 565968 118 565968 118 724 118 652
3500.971259: REMOVE empty empty 119 25404 119 25404 118 802 118 697
3500.971454: INACTIVE active empty 119 25580 119 25580 118 802 118 697

Sorted on the timestamps:
grep ungrant_exit trace* | awk '{print $3, $8, $20, $22, $24, $26, $28, $30, $32, $34, $36, $38}' | sort | less

3500.962328: REMOVE empty empty 118 380316 118 380316 118 724 118 652
3500.962386: INACTIVE empty empty 118 555684 118 555684 118 724 118 652
3500.962402: CREATE empty empty 118 380492 118 380492 118 724 118 652
3500.962458: INACTIVE empty empty 118 552532 118 552532 118 724 118 652
3500.962466: FSYNC_TS empty empty 118 552532 118 552532 118 724 118 652
3500.962476: REMOVE empty empty 118 380936 118 380936 118 724 118 652
3500.962534: INACTIVE empty empty 118 556304 118 556304 118 724 118 652
...
3500.979002: INACTIVE empty empty 118 437672 118 437672 118 802 118 697
3500.979185: CREATE empty empty 118 437848 118 437848 118 802 118 697
3500.979269: CREATE empty empty 118 438024 118 438024 118 802 118 697
3500.979462: INACTIVE empty empty 118 438024 118 438024 118 802 118 697
3500.979627: INACTIVE empty empty 119 20240 119 20240 118 802 118 697
3500.979657: REMOVE empty empty 118 438456 118 438456 118 802 118 697
3500.979713: REMOVE empty empty 118 438772 118 438772 118 802 118 697
3500.979815: CREATE empty empty 119 35872 119 35872 118 802 118 697
3501.000611: FSYNC_TS active empty 119 205428 119 205428 118 802 118 697


Maybe I have a corrupted version of his first trace, it looks like there are 2 series of log grant/write/head/tail sequences. These sequences are not even close to each other:

188.116687: FSYNC_TS empty empty 1 847894476 1 847894476 1 1655998 1 1655971
188.116939: FSYNC_TS empty empty 1 847894476 1 847894476 1 1655998 1 1655971
188.117755: CREATE empty empty 4440 166388 4440 166388 4440 312 4440 310
188.117784: FSYNC_TS empty empty 1 847894476 1 847894476 1 1655998 1 1655971
188.117902: FSYNC_TS empty empty 1 847894476 1 847894476 1 1655998 1 1655971
188.118249: CREATE empty empty 4440 166844 4440 166844 4440 312 4440 310
188.118350: CREATE empty empty 4440 167300 4440 167300 4440 312 4440 310
188.118628: FSYNC_TS empty empty 4440 167300 4440 167300 4440 312 4440 310
188.118837: FSYNC_TS empty empty 1 847894476 1 847894476 1 1655998 1 1655971
188.118868: FSYNC_TS empty empty 1 847894476 1 847894476 1 1655998 1 1655971

--Mark Tinguely.

<Prev in Thread] Current Thread [Next in Thread>