Still seeing hangs in xlog_grant_log_space

[Mark Tinguely]

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.