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 10:59:20 +0200
Cc: Arjan van de Ven <arjan@xxxxxxxxxxxxxxx>, xfs@xxxxxxxxxxx
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=uEnu2t9DStPfJTobwvg7X7n08+gIjBeXbFv7jBBUEb0=; b=I6W4ADiwiqbpGVN8Wh5IyxJaOofkx0uabz5wWWstIJ9QwFTPQ4NYsSv8GILY2NxBHA0CG0Ul+R0KOKlepakkeGb6EG6Z7mitWvwwEV4zMt4z/BKsRfkhwZT9OUMWn1WrNiv1J3Ez5TOVTrljWC6BbyK6bA79vr+eAW47TZJiLLM=
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=xapZ16n0+HSrMfbwZr4ZzfQwU0PCREtcRVHPfFfMQpX1cgIUwtMWZDyoG77r6EtiKlfBoSmeF6gbBkAIsCf9cSOAxHpSNzf+6c5Opir7DbkHHb3nCG/mTHir0gh4+82lSMeTIYfT5JL3DiQkxeQWxJxMYzrzjMSc+grnGin9G7c=
In-reply-to: <47BE6C5C.2000605@sgi.com>
References: <47B5DD9C.3080906@gmail.com> <47BE6C5C.2000605@sgi.com>
Sender: xfs-bounce@xxxxxxxxxxx
User-agent: Mozilla-Thunderbird 2.0.0.9 (X11/20080109)
Lachlan McIlroy wrote:
> Török Edwin wrote:
>> Hi,
>>
>> Using LatencyTOP 0.3, on the latest 2.6.25-git I see latencies of over a
>> second on __mark_ inode_dirty.
> These are the maximum latencies, right?  

Yes.
> 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 don't know how mark_inode_dirty ends up calling xfs_trans_commit, but
> It doesn't, but xfs_trans_commit() does eventually call
> mark_inode_dirty_sync()
> through the IOP_FORMAT() log item operation.  If we are committing a
> transaction
> that involves an inode then we must have just modified the inode so
> this is a
> good time to mark it dirty so that it gets written out to disk later.

Ok, then I misinterpreted the stacktrace, see below.
[@Arjan: are the stacktraces below valid?]
I thought mark_inode_dirty calls xfs_trans_commit().

>>
>> 7 93862 26567 _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
>> 1 96331 96331 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 xfs_vn_permission
>>
> These don't look like valid stacktraces - are you sure they aren't just
> the major offenders for latency delays?

Looking at this entry, I assumed stacktraces are meant to be interpreted
right to left (sys_read calls do_sync_read, etc.)

4 8 2 hrtick_set pipe_wait autoremove_wake_function pipe_read
do_sync_read autoremove_wake_function __resched_task
security_file_permission rw_verify_area vfs_read do_sync_read sys_read

However here,  if _xfs_trans_commit is calling __mark_inode_dirty,  I am
confused.

Also we have default_wake_function here, does that somehow invalidate
the stacktrace, or change the direction I should be reading it? Arjan?

7 93862 26567 _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

Best regards,
--Edwin


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