Uploaded image for project: 'Lustre'
  1. Lustre
  2. LU-14463

stack traces not being printed to console on RHEL8

Details

    • Bug
    • Resolution: Fixed
    • Critical
    • None
    • None
    • None
    • 3
    • 9223372036854775807

    Description

      I noticed in a recent test that instead of getting a stack trace printed to the console, all that is shown on the MDS console in the log is:
      https://testing.whamcloud.com/test_sets/92361cb8-6cb4-4045-a0df-c9efc31520ea

      [  508.376802] Call Trace TBD:
      [  508.378011] Pid: 31468, comm: mdt00_033 4.18.0-240.1.1.el8_lustre.x86_64 #1 SMP Fri Feb 19 20:34:57 UTC 2021
      [  508.379472] Call Trace TBD:
      [  508.379899] Pid: 31454, comm: mdt00_019 4.18.0-240.1.1.el8_lustre.x86_64 #1 SMP Fri Feb 19 20:34:57 UTC 2021
      [  508.381521] Call Trace TBD:
      

      which is not very useful. That message comes from patch https://review.whamcloud.com/35239 "LU-12400 libcfs: save_stack_trace_tsk if ARCH_STACKWALK". That patch was ostensibly to fix an issue with 5.4 kernels, but the MDS was running RHEL8.3 (4.18.0-240.1.1.el8_lustre.x86_64).

      At a minimum, in libcfs_call_trace() if tsk == current this should fall back to doing something useful:

              spin_lock(&st_lock);
              pr_info("Pid: %d, comm: %.20s %s %s\n", tsk->pid, tsk->comm,
                      init_utsname()->release, init_utsname()->version);
              if (task_dump_stack) {
                      pr_info("Call Trace:\n");
                      nr_entries = task_dump_stack(tsk, entries, MAX_ST_ENTRIES, 0);
                      for (i = 0; i < nr_entries; i++)
                              pr_info("[<0>] %pB\n", (void *)entries[i]);
              } else if (tsk == current) {
                      dump_stack();
              } else {
                      pr_info("can't show stack: kernel doesn't export save_stack_trace_tsk\n");
              }
              spin_unlock(&st_lock);
      

      so that the stack is printed in the common case.

      Attachments

        Issue Links

          Activity

            [LU-14463] stack traces not being printed to console on RHEL8
            pjones Peter Jones made changes -
            Fix Version/s Original: Lustre 2.15.0 [ 14791 ]
            adilger Andreas Dilger made changes -
            Resolution New: Fixed [ 1 ]
            Status Original: Open [ 1 ] New: Resolved [ 5 ]

            It looks like Shaun's patch https://review.whamcloud.com/40503 "LU-14099 build: Fix for unconfigured arch_stackwalk" has fixed this problem. I'm able to see an abbreviated, though still useful, stack trace on my RHEL8 server:

            [4439794.910865] Lustre: 1611:0:(osd_handler.c:1934:osd_trans_start()) myth-OST0000: credits 1351 > trans_max 1024
            [4439794.939134] Call Trace TBD:
            [4439794.941671] [<0>] libcfs_call_trace+0x6f/0x90 [libcfs]
            [4439794.944169] [<0>] osd_trans_start+0x4fd/0x520 [osd_ldiskfs]
            [4439794.946662] [<0>] ofd_precreate_objects+0x10f2/0x1f60 [ofd]
            [4439794.949034] [<0>] ofd_create_hdl+0x6a1/0x1740 [ofd]
            [4439794.951652] [<0>] tgt_request_handle+0xc78/0x1910 [ptlrpc]
            [4439794.954031] [<0>] ptlrpc_server_handle_request+0x31a/0xba0 [ptlrpc]
            [4439794.956444] [<0>] ptlrpc_main+0xba2/0x14a0 [ptlrpc]
            [4439794.958745] [<0>] kthread+0x112/0x130
            
            adilger Andreas Dilger added a comment - It looks like Shaun's patch https://review.whamcloud.com/40503 " LU-14099 build: Fix for unconfigured arch_stackwalk " has fixed this problem. I'm able to see an abbreviated, though still useful, stack trace on my RHEL8 server: [4439794.910865] Lustre: 1611:0:(osd_handler.c:1934:osd_trans_start()) myth-OST0000: credits 1351 > trans_max 1024 [4439794.939134] Call Trace TBD: [4439794.941671] [<0>] libcfs_call_trace+0x6f/0x90 [libcfs] [4439794.944169] [<0>] osd_trans_start+0x4fd/0x520 [osd_ldiskfs] [4439794.946662] [<0>] ofd_precreate_objects+0x10f2/0x1f60 [ofd] [4439794.949034] [<0>] ofd_create_hdl+0x6a1/0x1740 [ofd] [4439794.951652] [<0>] tgt_request_handle+0xc78/0x1910 [ptlrpc] [4439794.954031] [<0>] ptlrpc_server_handle_request+0x31a/0xba0 [ptlrpc] [4439794.956444] [<0>] ptlrpc_main+0xba2/0x14a0 [ptlrpc] [4439794.958745] [<0>] kthread+0x112/0x130
            adilger Andreas Dilger made changes -
            Summary Original: stack traces not being printed to console New: stack traces not being printed to console on RHEL8
            adilger Andreas Dilger made changes -
            Fix Version/s New: Lustre 2.15.0 [ 14791 ]

            BTW Shaun pushed a patch - https://review.whamcloud.com/#/c/40503. Does this resolve it?

            I don't think for x86 at least. The changes under CONFIG_ARCH_STACKWALK, where the Call Trace TBD: message is printed, are a no-op. It is hard to say for sure, since the review-ldiskfs sanity test_422 printed the stacks correctly, but it ran with EL8.2 on the MDS and I think the symbol_get() "fix" only appeared with EL8.3. I think the stack_trace_save_tsk() copy may allow this to work on x86 as well.

            adilger Andreas Dilger added a comment - BTW Shaun pushed a patch - https://review.whamcloud.com/#/c/40503 . Does this resolve it? I don't think for x86 at least. The changes under CONFIG_ARCH_STACKWALK , where the Call Trace TBD: message is printed, are a no-op. It is hard to say for sure, since the review-ldiskfs sanity test_422 printed the stacks correctly, but it ran with EL8.2 on the MDS and I think the symbol_get() "fix" only appeared with EL8.3. I think the stack_trace_save_tsk() copy may allow this to work on x86 as well.
            adilger Andreas Dilger made changes -
            Link New: This issue is related to LU-14099 [ LU-14099 ]

            James, that is patch https://review.whamcloud.com/33018 "LU-9859 libcfs: add watchdog for ptlrpc service threads", but as I posted in my previous comment, the delayed work timer is in the context of another thread, so dump_stack() will not work in that case (it does not take a task_struct argument).

            What does look promising is that stack_trace_save_tsk() looks like it is only a thin wrapper around save_stack_trace_tsk(), and that function is exported, so it may be that instead of calling symbol_get("stack_trace_save_tsk") (which doesn't work anymore) we just make a copy of that function:

            unsigned int stack_trace_save_tsk(struct task_struct *task,
                                              unsigned long *store, unsigned int size,
                                              unsigned int skipnr)
            {               
                    struct stack_trace trace = {
                            .entries        = store,
                            .max_entries    = size,
                            /* skip this function if they are tracing us */
                            .skip   = skipnr + (current == task),
                    };
            
                    save_stack_trace_tsk(task, &trace);
                    return trace.nr_entries;
            }
            
            adilger Andreas Dilger added a comment - James, that is patch https://review.whamcloud.com/33018 " LU-9859 libcfs: add watchdog for ptlrpc service threads ", but as I posted in my previous comment, the delayed work timer is in the context of another thread, so dump_stack() will not work in that case (it does not take a task_struct argument). What does look promising is that stack_trace_save_tsk() looks like it is only a thin wrapper around save_stack_trace_tsk() , and that function is exported, so it may be that instead of calling symbol_get("stack_trace_save_tsk") (which doesn't work anymore) we just make a copy of that function: unsigned int stack_trace_save_tsk(struct task_struct *task, unsigned long *store, unsigned int size, unsigned int skipnr) { struct stack_trace trace = { .entries = store, .max_entries = size, /* skip this function if they are tracing us */ .skip = skipnr + (current == task), }; save_stack_trace_tsk(task, &trace); return trace.nr_entries; }

            BTW Shaun pushed a patch - https://review.whamcloud.com/#/c/40503. Does this resolve it?

            simmonsja James A Simmons added a comment - BTW Shaun pushed a patch - https://review.whamcloud.com/#/c/40503.  Does this resolve it?

            It looks like the only place that is calling libcfs_debug_dumpstack() with a non-NULL argument is in ptlrpc_watchdog_fire(), but unfortunately this delayed work is happening in a different context from the stack being dumped, so the tsk == current case does not help that case (though it would at least fix all of the other callers):
            https://testing.whamcloud.com/test_sets/7a00c660-73d0-46f9-8d4b-8ff6f8a2dbac (looking at the test_425 MDS logs):

            00000100:02000400:0.0:1612373649.290722:0:692869:0:(service.c:2652:ptlrpc_watchdog_fire()) mdt00_001: service thread pid 710575 was inactive for 40.008 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
            

            The Dumping the stack trace message is printed by PID 692869 but the thread being dumped is PID 710575.

            adilger Andreas Dilger added a comment - It looks like the only place that is calling libcfs_debug_dumpstack() with a non-NULL argument is in ptlrpc_watchdog_fire() , but unfortunately this delayed work is happening in a different context from the stack being dumped, so the tsk == current case does not help that case (though it would at least fix all of the other callers): https://testing.whamcloud.com/test_sets/7a00c660-73d0-46f9-8d4b-8ff6f8a2dbac (looking at the test_425 MDS logs): 00000100:02000400:0.0:1612373649.290722:0:692869:0:(service.c:2652:ptlrpc_watchdog_fire()) mdt00_001: service thread pid 710575 was inactive for 40.008 seconds. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: The Dumping the stack trace message is printed by PID 692869 but the thread being dumped is PID 710575 .

            People

              wc-triage WC Triage
              adilger Andreas Dilger
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: