xfs
[Top] [All Lists]

Re: Marking inode dirty latency > 1000 msec on XFS!

To: lachlan@xxxxxxx
Subject: Re: Marking inode dirty latency > 1000 msec on XFS!
From: Török Edwin <edwintorok@xxxxxxxxx>
Date: Fri, 22 Feb 2008 12:20:23 +0200
Cc: Arjan van de Ven <arjan@xxxxxxxxxxxxxxx>, xfs@xxxxxxxxxxx, David Chinner <dgc@xxxxxxx>
Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:message-id:date:from:user-agent:mime-version:to:cc:subject:references:in-reply-to:content-type:content-transfer-encoding; bh=Id6pvyA1izoZVb5xoBI0Hv4rZnLuNeGpHH0be9d/cRs=; b=qB/b9lZWcTNFF+itW/bcp5RPi+IylepRtYrt3zgfDzGU4XosJ/4ORJ70K3Bi38HI9Hmt1ciIO12WMHVKqaWt/8nchM3JwAdfXPfSPRRg3+8ItFjAYEjIqESkNmpgzr54Yy6rjK1U6/HD+lEWHV8jU2qR8Ticj4lWCFbVllIMUkQ=
Domainkey-signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=message-id:date:from:user-agent:mime-version:to:cc:subject:references:in-reply-to:content-type:content-transfer-encoding; b=A8zzpr+knQVp07iowlnZf4zYeyBSX85S+mA0kuPVBZNP+6SvD75jIUgJBmd+MNGuDxkytfldiYnojYUOzdjmXKzfgs+qSmU3mQ+vXXnObU/fYV5RDJEg69M6h48ReBB4OsVsqfArwh3XcY7tQdIoFl2n/DlBc5yBRqVNMU7oE8E=
In-reply-to: <47BE8EE8.5020005@xxxxxxxxx>
References: <47B5DD9C.3080906@xxxxxxxxx> <47BE6C5C.2000605@xxxxxxx> <47BE8EE8.5020005@xxxxxxxxx>
Sender: xfs-bounce@xxxxxxxxxxx
User-agent: Mozilla-Thunderbird 2.0.0.9 (X11/20080109)
Török Edwin wrote:
>> What would be useful here is the
>> average latency time.  The average might actually be quite low but if
>> just
>> once we have a maximum that is unusually large then just looking at that
>> figure can be misleading.
>>     
>
> I'll try to collect the raw numbers from /proc/latency_stats, that
> contain a count, total time, and max time.

I was not able to reproduce the 1 second latency with David Chinner's
reduce xaild wakeups patch, the maximum latency  I got was 685 msec.

See below the numbers I got from /proc/latency_stats, the counters are
reset every 30 seconds, so I did more captures, and noted the top 3 (for
the 2nd case).

Notice the irq_exit in the first case (w/o patch), which is present in
the top latencies. There is no irq_exit in the second case.
@Arjan: I am not sure if stacktraces containing irq_exit() are entirely
valid, or the stacktrace should be stopped when it is encountered.

Here are the numbers w/o the wakeups patch (1 capture of grep mark_inode
/proc/latency_stats)

<count> <sum> <maximum> <stacktrace>
----------------
2 47699 36897 xfs_buf_free default_wake_function xfs_buf_lock xfs_getsb
xfs_trans_getsb xfs_trans_apply_sb_deltas _xfs_trans_commit
xfs_dir_createname kmem_zone_alloc __mark_inode_dirty igrab xfs_create
1 1045646 1045646 wake_up_state default_wake_function xfs_buf_lock
xfs_getsb xfs_trans_getsb xfs_trans_apply_sb_deltas _xfs_trans_commit
irq_exit xfs_dir_createname kmem_zone_alloc __mark_inode_dirty igrab
1 818946 818946 default_wake_function xfs_buf_lock xfs_getsb
xfs_trans_getsb xfs_trans_apply_sb_deltas _xfs_trans_commit irq_exit
xfs_dir_createname kmem_zone_alloc __mark_inode_dirty igrab xfs_create

Average = 478072 usecs
-----------------

Here are the numbers w/ the wakeups patch:(3 captures of grep mark_inode
/proc/latency_stats)
<count> <sum> <maximum> <stacktrace>
-----------
1 685021 685021 xfs_buf_free default_wake_function xfs_buf_lock
xfs_getsb xfs_trans_getsb xfs_trans_apply_sb_deltas _xfs_trans_commit
xfs_dir_createname xfs_dir_ialloc __mark_inode_dirty igrab xfs_create

Only one sample, average=max
----------
20 153016 8989 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_write
xfs_log_write _xfs_trans_commit __mark_inode_dirty igrab xfs_create
xfs_vn_mknod security_inode_permission

Average: 153016/20 = 7650 usecs
----------
28 250553 28743 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_write
xfs_log_write _xfs_trans_commit __mark_inode_dirty igrab xfs_create
xfs_vn_mknod security_inode_permission
4 32829 8843 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_state_want_sync
xlog_write xfs_log_write _xfs_trans_commit __mark_inode_dirty igrab
xfs_create xfs_vn_mknod
1 7554 7554 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_write
xfs_log_write _xfs_trans_commit xfs_bmap_last_offset xfs_dir_createname
xfs_dir_ialloc __mark_inode_dirty igrab
1 7011 7011 _xfs_buf_ioapply xfs_buf_iorequest xlog_bdstrat_cb
default_wake_function xlog_state_get_iclog_space xlog_write
__mark_inode_dirty kmem_free xfs_buf_item_format xfs_log_write
_xfs_trans_commit igrab
28 250553 28743 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_write
xfs_log_write _xfs_trans_commit __mark_inode_dirty igrab xfs_create
xfs_vn_mknod security_inode_permission
4 32829 8843 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_state_want_sync
xlog_write xfs_log_write _xfs_trans_commit __mark_inode_dirty igrab
xfs_create xfs_vn_mknod
1 7554 7554 _xfs_buf_ioapply default_wake_function
xlog_state_get_iclog_space xlog_state_release_iclog xlog_write
xfs_log_write _xfs_trans_commit xfs_bmap_last_offset xfs_dir_createname
xfs_dir_ialloc __mark_inode_dirty igrab
1 7011 7011 _xfs_buf_ioapply xfs_buf_iorequest xlog_bdstrat_cb
default_wake_function xlog_state_get_iclog_space xlog_write
__mark_inode_dirty kmem_free xfs_buf_item_format xfs_log_write
_xfs_trans_commit igra

Average = 8762 usecs

Best regards,
--Edwin


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