[LU-2624] Stop of ptlrpcd threads is long

• Type: Bug
• Resolution: Fixed
• Priority: Minor
• Fix Version/s: Lustre 2.4.0
• Affects Version/s: Lustre 2.2.0, Lustre 2.3.0, Lustre 2.4.0, Lustre 2.1.5
• Environment: lustre 2.1.3; bullxlinux 6.1 (based on redhat 6.1); machine with 32 CPUs
• Severity: 3

Epic

ptlrpc

• Assignee: Bruno Faccini (Inactive)
• Reporter: Gregoire Pichon

Description

The stop of ptlrpcd threads lasts more than one second per thread. On hardware with large number of cores this lead to a few minutes to unload ptlrpc module.

# lscpu | grep "^CPU(s)"
CPU(s):                32
# ps -ef | grep ptlrpcd
root      7301     2  0 10:58 ?        00:00:00 [ptlrpcd_rcv]
root      7302     2  0 10:58 ?        00:00:00 [ptlrpcd_0]
root      7303     2  0 10:58 ?        00:00:00 [ptlrpcd_1]
root      7304     2  0 10:58 ?        00:00:00 [ptlrpcd_2]
root      7305     2  0 10:58 ?        00:00:00 [ptlrpcd_3]
root      7306     2  0 10:58 ?        00:00:00 [ptlrpcd_4]
root      7307     2  0 10:58 ?        00:00:00 [ptlrpcd_5]
root      7308     2  0 10:58 ?        00:00:00 [ptlrpcd_6]
root      7309     2  0 10:58 ?        00:00:00 [ptlrpcd_7]
root      7310     2  0 10:58 ?        00:00:00 [ptlrpcd_8]
root      7311     2  0 10:58 ?        00:00:00 [ptlrpcd_9]
root      7312     2  0 10:58 ?        00:00:00 [ptlrpcd_10]
root      7313     2  0 10:58 ?        00:00:00 [ptlrpcd_11]
root      7314     2  0 10:58 ?        00:00:00 [ptlrpcd_12]
root      7315     2  0 10:58 ?        00:00:00 [ptlrpcd_13]
root      7316     2  0 10:58 ?        00:00:00 [ptlrpcd_14]
root      7317     2  0 10:58 ?        00:00:00 [ptlrpcd_15]
root      7318     2  0 10:58 ?        00:00:00 [ptlrpcd_16]
root      7319     2  0 10:58 ?        00:00:00 [ptlrpcd_17]
root      7320     2  0 10:58 ?        00:00:00 [ptlrpcd_18]
root      7321     2  0 10:58 ?        00:00:00 [ptlrpcd_19]
root      7322     2  0 10:58 ?        00:00:00 [ptlrpcd_20]
root      7323     2  0 10:58 ?        00:00:00 [ptlrpcd_21]
root      7324     2  0 10:58 ?        00:00:00 [ptlrpcd_22]
root      7325     2  0 10:58 ?        00:00:00 [ptlrpcd_23]
root      7326     2  0 10:58 ?        00:00:00 [ptlrpcd_24]
root      7327     2  0 10:58 ?        00:00:00 [ptlrpcd_25]
root      7328     2  0 10:58 ?        00:00:00 [ptlrpcd_26]
root      7329     2  0 10:58 ?        00:00:00 [ptlrpcd_27]
root      7330     2  0 10:58 ?        00:00:00 [ptlrpcd_28]
root      7331     2  0 10:58 ?        00:00:00 [ptlrpcd_29]
root      7332     2  0 10:58 ?        00:00:00 [ptlrpcd_30]
root      7333     2  0 10:58 ?        00:00:00 [ptlrpcd_31]
# time modprobe -r ptlrpc
real	1m7.204s
user	0m0.000s
sys	0m0.030s

Comments

[Bruno Faccini (Inactive)]

Hello Gregoire, I agree with Andreas, there must be something else to explain the >1mn for the rmmod.

BTW, each or at least groups of the ptlrpcd thread would execute in parallel on multiple Cores (depending on their scheduling policy) thus the timing you get would be the max of all execution-sets which looks too long for me ...

Can you reproduce the problem and ensure that you enabled the full debug-traces before and also you delimited the rmmod timing period with BEGIN/END markers ??

A ps output showing the ptlrpcd pids would be helpful too.

[Gregoire Pichon]

I don't think there is something wrong.

In ptlrpcd() routine, the ptlrpcd thread loops waiting for work to do. The wait condition has a timeout of 1 second when the set is idle. When the thread is notified to stop, it performs one more loop before exiting. That explains why it lasts at least one second for each thread to stop.

        do {
                struct l_wait_info lwi;
                int timeout;

                rc = lu_env_refill(&env);
                if (rc != 0) {
                        /*
                         * XXX This is very awkward situation, because
                         * execution can neither continue (request
                         * interpreters assume that env is set up), nor repeat
                         * the loop (as this potentially results in a tight
                         * loop of -ENOMEM's).
                         *
                         * Fortunately, refill only ever does something when
                         * new modules are loaded, i.e., early during boot up.
                         */
                        CERROR("Failure to refill session: %d\n", rc);
                        continue;
                }

                timeout = ptlrpc_set_next_timeout(set);
                lwi = LWI_TIMEOUT(cfs_time_seconds(timeout ? timeout : 1),
                                  ptlrpc_expired_set, set);

                lu_context_enter(&env.le_ctx);
                l_wait_event(set->set_waitq,
                             ptlrpcd_check(&env, pc), &lwi);
                lu_context_exit(&env.le_ctx);

                /*
                 * Abort inflight rpcs for forced stop case.
                 */
                if (cfs_test_bit(LIOD_STOP, &pc->pc_flags)) {
                        if (cfs_test_bit(LIOD_FORCE, &pc->pc_flags))
                                ptlrpc_abort_set(set);
                        exit++;
                }

                /*
                 * Let's make one more loop to make sure that ptlrpcd_check()
                 * copied all raced new rpcs into the set so we can kill them.
                 */
        } while (exit < 2);

[Andreas Dilger]

Do you have any idea why it takes do long to stop each thread? This might also be a sign of something else wrong (e.g. if there are structures being kept around to long and needing to be freed at the end).

[Bruno Faccini (Inactive)]

Hello Gregoire !!
Thank's for the report and the fix proposal already.
Will review it and give you feedback soon.
Bye.

[Gregoire Pichon]

http://review.whamcloud.com/5039

[Gregoire Pichon]

I am going to post a fix.

With the fix, stop of ptlrpcd threads is dramatically reduced:

# time modprobe -r ptlrpc

real	0m6.675s
user	0m0.000s
sys	0m0.030s