Re: long hangs when deleting large directories (3.0-rc3)

Dave Chinner
2011-06-21T04:25:19Z

On Mon, Jun 20, 2011 at 01:13:59PM +0200, Markus Trippelsdorf wrote:
> On 2011.06.20 at 08:03 +0200, Markus Trippelsdorf wrote:
> > OK. I was able to reproduce the same hang on a conventional 512 sector drive.
> > The partition that I've used was the predecessor to the one on the 4k drive. So
> > it saw roughly the same usage pattern.
> > This is the output of "dstat -cdyl -C 0,1,2,3 -D sdc --disk-tps" during the
> > hang:
> >
> > -------cpu0-usage--------------cpu1-usage--------------cpu2-usage--------------cpu3-usage------ --dsk/sdc-- ---system-- ---load-avg--- --dsk/sdc--
> > usr sys idl wai hiq siq:usr sys idl wai hiq siq:usr sys idl wai hiq siq:usr sys idl wai hiq siq| read writ| int csw | 1m 5m 15m |reads writs
> >
> > 0 0 100 0 0 0: 1 0 99 0 0 0: 0 1 99 0 0 0: 1 0 99 0 0 0| 0 0 | 249 354 |0.33 0.58 0.38| 0 0
> > 0 0 100 0 0 0: 0 0 100 0 0 0: 0 0 100 0 0 0: 0 0 100 0 0 0| 0 0 | 244 228 |0.33 0.58 0.38| 0 0
> > 1 2 97 0 0 0: 0 1 99 0 0 0: 0 1 99 0 0 0: 0 1 99 0 0 0| 0 0 | 559 614 |0.33 0.58 0.38| 0 0
> > 0 0 100 0 0 0: 1 0 99 0 0 0: 1 0 99 0 0 0: 1 0 99 0 0 0| 0 0 | 341 426 |0.33 0.58 0.38| 0 0
> > 1 0 99 0 0 0: 1 4 95 0 0 0: 0 1 99 0 0 0: 1 16 83 0 0 0| 0 0 | 874 796 |0.33 0.58 0.38| 0 0
> > 2 50 49 0 0 0: 1 9 90 0 0 0: 1 9 90 0 0 0: 1 23 76 0 0 0| 0 6400k|2803 2073 |0.46 0.60 0.39| 0 25
> > 1 29 70 0 0 0: 1 1 98 0 0 0: 1 9 90 0 0 0: 1 53 46 0 0 0| 0 6400k|2047 1414 |0.46 0.60 0.39| 0 25
> > 0 4 96 0 0 0: 0 0 100 0 0 0: 1 19 80 0 0 0: 0 80 20 0 0 0| 0 2048k|1425 685 |0.46 0.60 0.39| 0 8
> > 2 1 97 0 0 0: 1 6 93 0 0 0: 0 5 95 0 0 0: 0 83 17 0 0 0| 0 4608k|1624 849 |0.46 0.60 0.39| 0 18
> > 2 45 53 0 0 0: 1 16 83 0 0 0: 3 20 77 0 0 0: 1 15 84 0 0 0| 0 6400k|2420 1984 |0.46 0.60 0.39| 0 26
> > 1 19 80 0 0 0: 2 8 90 0 0 0: 0 33 67 0 0 0: 0 33 67 0 0 0| 0 6400k|2694 2134 |0.59 0.63 0.40| 0 25
> > 2 7 91 0 0 0: 2 1 97 0 0 0: 1 0 99 0 0 0: 0 49 10 41 0 0| 0 8269k|1865 1571 |0.59 0.63 0.40| 0 363
> > 1 1 98 0 0 0: 1 1 98 0 0 0: 1 1 98 0 0 0: 0 1 0 99 0 0| 0 4778k|1509 1639 |0.59 0.63 0.40| 0 410
> > 2 0 98 0 0 0: 2 1 97 0 0 0: 1 1 98 0 0 0: 2 0 0 98 0 0| 0 5318k|1663 1809 |0.59 0.63 0.40| 0 426
> > 1 1 98 0 0 0: 2 7 91 0 0 0: 1 0 99 0 0 0: 1 0 0 99 0 0| 0 5446k|1659 1806 |0.59 0.63 0.40| 0 432
> > 0 1 99 0 0 0: 1 0 99 0 0 0: 2 0 98 0 0 0: 0 1 17 82 0 0| 0 5472k|1572 1837 |0.62 0.63 0.40| 0 439
> > 2 0 98 0 0 0: 2 2 96 0 0 0: 0 1 99 0 0 0: 0 1 99 0 0 0| 0 397k|1058 1049 |0.62 0.63 0.40| 0 36
> > 1 1 98 0 0 0: 1 1 98 0 0 0: 1 1 98 0 0 0: 0 0 100 0 0 0| 0 0 | 617 689 |0.62 0.63 0.40| 0 0
> > 9 4 87 0 0 0: 4 0 96 0 0 0: 1 1 98 0 0 0: 8 6 87 0 0 0| 0 0 |1234 1961 |0.62 0.63 0.40| 0 0
> > 0 1 99 0 0 0: 1 1 98 0 0 0: 0 1 99 0 0 0: 0 1 99 0 0 0| 0 0 | 391 403 |0.62 0.63 0.40| 0 0
> > 1 0 99 0 0 0: 1 1 98 0 0 0: 0 0 100 0 0 0: 0 0 100 0 0 0| 0 0 | 366 375 |0.57 0.62 0.40| 0 0

What is the resolution of the samples here? Where did the hang occur
during this output?

FWIW, Can you capture the hang while running 'iostat -x -d -m 1' so
we can see what is happening with queue depths, average Io sizes,
etc?

> Here are two more examples. The time when the hang occurs is marked with
> "=>":
> ------cpu0-usage--------------cpu1-usage--------------cpu2-usage--------------cpu3-usage------ --dsk/sdb-- ---system-- ---load-avg--- --dsk/sdb--
> usr sys idl wai hiq siq:usr sys idl wai hiq siq:usr sys idl wai hiq siq:usr sys idl wai hiq siq| read writ| int csw | 1m 5m 15m |reads writs
.....
> 1 10 89 0 0 0: 2 38 61 0 0 0: 1 8 81 10 0 0: 0 64 36 0 0 0| 0 4476k|2378 2010 |1.12 0.59 0.28| 0 146
> =>0 0 100 0 0 0: 0 1 99 0 0 0: 0 1 0 99 0 0: 0 100 0 0 0 0| 0 0 |1237 283 |1.12 0.59 0.28| 0 0
> 0 27 73 0 0 0: 1 0 99 0 0 0: 0 0 47 53 0 0: 0 56 44 0 0 0| 0 5812k|1596 857 |1.12 0.59 0.28| 0 182
.....
> 7 26 67 0 0 0: 4 1 95 0 0 0: 1 37 62 0 0 0: 3 38 59 0 0 0| 0 864k|2904 2806 |0.70 0.65 0.40| 0 33
> =>2 1 97 0 0 0: 1 0 99 0 0 0: 0 1 99 0 0 0: 0 100 0 0 0 0| 0 0 |1725 639 |0.89 0.69 0.41| 0 0
> 1 1 98 0 0 0: 2 1 97 0 0 0: 2 1 97 0 0 0: 0 71 29 0 0 0| 0 3968k|1793 852 |0.89 0.69 0.41| 0 123
.....

So in both cases here the hang occurs when there is -zero- IO
occurring, and a CPU has pegged at 100% in system time. That's CPU
bound doing <something>. It is possible that the CPU is getting
caught in a loop somewhere or has a -lot- of processing to do before
progress is made.

I know a CIL commit can take some time to process all the
objects in a checkpoint, but I haven't seen anything like this.
You've only got a relatively small log (100MB) and you're only
removing a kernel source tree, so there really shouldn't be an
excessive number of objects built up to process per checkpoint.

FWIW, I'm pretty sure a CPU getting stuck like this in the
filesystem code should not be causing problems with X or other
non-filesystem workloads. There's 3 idle CPU cores and you are
running a preemptible kernel, so I really can't see why system time
spent in XFS would cause mouse or keyboard updates to not be
processed in a timely manner. We really need to know what is
consuming all that CPU time.

That is, you really need to get a profile of the rm -rf process - or
whatever is consuming the CPU time - (e.g. via perf or ftrace)
across the hang to so we can narrow down the potential cause of the
latency. Speaking of which, latencytop might be helpful in
identifying where input is getting held up....

Cheers,

Dave.
--
Dave Chinner
david@fromorbit.com