[LU-4797] ASSERTION( cl_lock_is_mutexed(slice->cls_lock) ) failed

• Type: Bug
• Resolution: Duplicate
• Priority: Major
• Affects Version/s: Lustre 2.4.2
• Severity: 3
• Assignee: Jinshan Xiong (Inactive)
• Reporter: Sebastien Buisson (Inactive)

Description

Hi,

After 3 days in production with Lustre 2.4.2, CEA is suffering from the following "assertion failed" issue about 5 times a day:

LustreError: 4089:0:(lovsub_lock.c:103:lovsub_lock_state()) ASSERTION( cl_lock_is_mutexed(slice->cls_lock) ) failed:
LustreError: 4089:0:(lovsub_lock.c:103:lovsub_lock_state()) LBUG
Pid: 4089, comm: %%AQC.P.I.O

Call Trace:
 [<ffffffffa0af4895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
 [<ffffffffa0af4e97>] lbug_with_loc+0x47/0xb0 [libcfs]
 [<ffffffffa1065d51>] lovsub_lock_state+0x1a1/0x1b0 [lov]
 [<ffffffffa0bd7a88>] cl_lock_state_signal+0x68/0x160 [obdclass]
 [<ffffffffa0bd7bd5>] cl_lock_state_set+0x55/0x190 [obdclass]
 [<ffffffffa0bdb8d9>] cl_enqueue_try+0x149/0x300 [obdclass]
 [<ffffffffa105e0da>] lov_lock_enqueue+0x22a/0x850 [lov]
 [<ffffffffa0bdb88c>] cl_enqueue_try+0xfc/0x300 [obdclass]
 [<ffffffffa0bdcc7f>] cl_enqueue_locked+0x6f/0x1f0 [obdclass]
 [<ffffffffa0bdd8ee>] cl_lock_request+0x7e/0x270 [obdclass]
 [<ffffffffa0be2b8c>] cl_io_lock+0x3cc/0x560 [obdclass]
 [<ffffffffa0be2dc2>] cl_io_loop+0xa2/0x1b0 [obdclass]
 [<ffffffffa10dba90>] ll_file_io_generic+0x450/0x600 [lustre]
 [<ffffffffa10dc9d2>] ll_file_aio_write+0x142/0x2c0 [lustre]
 [<ffffffffa10dccbc>] ll_file_write+0x16c/0x2a0 [lustre]
 [<ffffffff811895d8>] vfs_write+0xb8/0x1a0
 [<ffffffff81189ed1>] sys_write+0x51/0x90
 [<ffffffff81091039>] ? sys_times+0x29/0x70
 [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b

This issue is very similar to LU-4693, which is itself a duplicate of LU-4692, for which there is unfortunately no fix yet.

Please ask if you need additional information that could help the diagnostic and resolution of the problem.

Sebastien.

Issue Links

• is duplicated by: LU-4693 (lovsub_lock.c:103:lovsub_lock_state()) ASSERTION( cl_lock_is_mutexed(slice->cls_lock) ) failed:
• is related to: LU-4558 Crash in cl_lock_put on racer
• is related to: LU-4591 Related cl_lock failures on master/2.5

Comments

[Zhenyu Xu]

update: tried taskset, usleep 1000000, each cpu took 250 echo taskes, 2 VM nodes, each node has 2 cpus, haven't got the hit yet.

[Zhenyu Xu]

my wait time is 1.5x of the initial reproducer, I'll try the taskset.

[Antoine Percher]

About the testcase :

• the waiting time is too large than the initial reproducer by x15
• fix the run a processor/core with taskset for example when
  you run /tmp/reproducer.sh on the 2 nodes
  for cpu in $(seq 0 5) # nb cpus nodes
  taskset -c $cpu /tmp/reproducer.sh & ; done
• My first testcase was without usleep and 32 task/process by nodes
  and 1000 write/echo by task
• no lustre trace enable

[Sebastien Buisson (Inactive)]

Bobijam,

To make it clear, 2.4.2 is the first b2_4 release used at CEA, so we are not comparing with 2.4.1, but with 2.1.6.

Sebastien.

[Bruno Faccini (Inactive)]

Aurelien, concerning the evictions likely to be reproduced on site with this script, is it also possible to get a Lustre debug-log, at least from evicted Client side and with the full debug mask/traces enabled ?

[Bruno Faccini (Inactive)]

Seb, sorry to only answer to your own comment/reply on "21/Mar/14 3:53 PM", so yes it could be useful as a 1st debugging info to get the debug-log content extracted from the crash-dump. BTW, I hope that you run with a default debug-levels mask that will be enough to gather accurate traces for this problem ??...

[Aurelien Degremont (Inactive)]

Please note that Sebastien's script is not a reproducer of this crash, but something similar to the workload that leads to this crash. This code only easily triggers a lot of evictions.

[Jinshan Xiong (Inactive)]

Is it possible to collect a crash dump for this issue?

The only difference between 2.4.1 and 2.4.2 is LU-3027, there are two patches landed for it. Can anyone please revert them and try again? Probably this way we can get some clues for this issue.

[Zhenyu Xu]

I've been being trying the reproduce script since yesterday, haven't gotten a hit yet. I did a little change for my VM test environment.

$ cat ~/tmp/reproducer.sh
#!/bin/bash

ls > /dev/null &
PID=$!

for i in $(seq 1 10000)
do
echo $PID - $i
usleep $((($PID * 100) + 1500000))
echo "$(date) $(date '+%N') $PID-$i ***** testing write in append mode" >> /mnt/lustre/file
done

and on 2 nodes, run "$~/tmp/reproducer.sh &" five times, I think the basic idea is the same.

Sebastien, How long would it rehit the issue in your case?

[Christopher Morrone (Inactive)]

LLNL also hit this in testing Lustre version 2.4.2-6chaos on a Lustre client.

[Sebastien Buisson (Inactive)]

The workload should be reproduced by launching the script run_reproducer_2.sh with 4 processes on 2 nodes.

::::::::::::::
run_reproducer_2.sh
::::::::::::::
#!/bin/bash
sleeptime=$(( ( ${SLURM_PROCID} * 10000 ) + 1000000 ))
reproducer2.sh 10 /<path>/mylog ${sleeptime} ${SLURM_JOBID}_${SLURM_PROCID}
::::::::::::::
reproducer2.sh
::::::::::::::
#!/bin/bash
#
for i in $(seq 1 $1)
do
  usleep $3
  echo $(date) $(date '+%N') $4 $3 testing write in append mode >> $2
done