Skip to content

Debug: enable kernel boot up time measurement #9

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
michael2012z merged 1 commit into from
Mar 9, 2022
Merged

Debug: enable kernel boot up time measurement #9

michael2012z merged 1 commit into from
Mar 9, 2022

Conversation

@jongwu
Copy link

@jongwu jongwu commented Mar 3, 2022 •
edited
Loading

To measure kernel boot up time, reserved region in pl011 is used as trap
MMIO region to record kernel boot timestamp.
For now, we trap at 2 point: the first is nearly the first instruction of
kernel start; the second is just before call the init bin for userspace.
These 2 points can cover the whole kernel boot time.

Signed-off-by: Jianyong Wu jianyong.wu@arm.com

@jongwu
Copy link
Author

jongwu commented Mar 3, 2022

@justin-he

@jongwu jongwu force-pushed the bench-arm branch 4 times, most recently from 20f829a to c442233 Compare March 3, 2022 08:58
rbradford
rbradford reviewed Mar 3, 2022
View reviewed changes
Copy link
Member

@rbradford rbradford left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would it not be better to write it at the same location as the x86 point?

@jongwu
Copy link
Author

jongwu commented Mar 4, 2022

Hi @rbradford -, As the debug IO port emulation bases on a device, we need find a way to access the mmio region and there are 2 ways:

  1. access the physical address before MMU enable, where all the address are physical. It is at the very beginning of kernel boot and I try it but failed;
  2. access the virtual address of the mmio region that we must wait for the initialization of the device. It is the way this PR does.

It's better to set the first trap point at the beginning of "start_kernel" or even before it. But I must figure out why I fail to do that. I will leave it in 'TODO'. Also, the earlycon is initialized very early and I think we can bear the delay compared with trap at the beginning of start_kernel.

@jongwu
Copy link
Author

jongwu commented Mar 4, 2022

@MrXinWang @michael2012z

@jongwu jongwu force-pushed the bench-arm branch 2 times, most recently from c4b9d92 to cb4a44a Compare March 7, 2022 05:23
@jongwu
Debug: enable kernel boot up time measurement
00377a5 
To measure kernel boot up time, reserved region in pl011 is used as trap
MMIO region to record kernel boot timestamp.
For now, we trap at 2 point: the first is nearly the first instruction of
kernel start; the second is just before call the init bin for userspace.
These 2 points can cover the whole kernel boot time.

Signed-off-by: Jianyong Wu <jianyong.wu@arm.com>
@jongwu
Copy link
Author

jongwu commented Mar 7, 2022

Hi @rbradford -, I have changed the trap points. Now, the first point at the beginning of kernel which nearly the first code executed in kernel which it's ahead of x86 does as I can't let it trap at the beginning of start_kernel ; the second moved to the same location with x86.

@MrXinWang
Copy link
Member

MrXinWang commented Mar 8, 2022

Hi @rbradford @michael2012z , AFAIK, I think for Arm64 platform, the start_kernel is the C code entry of the kernel. Before that Arm64 needs to do some initialization (CPU, memory, MMU, stack, etc.) in assembly code and then jump to start_kernel. So to me what @jongwu does in this PR basically can enable the measurement from the very beginning of the kernel start, hence makes sense to me.

@rbradford
Copy link
Member

rbradford commented Mar 8, 2022

Okay, cool. Do you need Cloud Hypervisor changes too?

@michael2012z
Copy link
Member

michael2012z commented Mar 9, 2022

Okay, cool. Do you need Cloud Hypervisor changes too?

Yes, the change on Cloud Hypervisor will come soon.

@michael2012z michael2012z merged commit f8b40f6 into cloud-hypervisor:ch-5.15.12 Mar 9, 2022
@michael2012z michael2012z mentioned this pull request Mar 9, 2022
Merged
rbradford pushed a commit that referenced this pull request Jan 14, 2025
@gregkh
nvme-rdma: unquiesce admin_q before destroy it
05b436f 
[ Upstream commit 5858b68 ]

Kernel will hang on destroy admin_q while we create ctrl failed, such
as following calltrace:

PID: 23644    TASK: ff2d52b40f439fc0  CPU: 2    COMMAND: "nvme"
 #0 [ff61d23de260fb78] __schedule at ffffffff8323bc15
 #1 [ff61d23de260fc08] schedule at ffffffff8323c014
 #2 [ff61d23de260fc28] blk_mq_freeze_queue_wait at ffffffff82a3dba1
 #3 [ff61d23de260fc78] blk_freeze_queue at ffffffff82a4113a
 #4 [ff61d23de260fc90] blk_cleanup_queue at ffffffff82a33006
 #5 [ff61d23de260fcb0] nvme_rdma_destroy_admin_queue at ffffffffc12686ce
 #6 [ff61d23de260fcc8] nvme_rdma_setup_ctrl at ffffffffc1268ced
 #7 [ff61d23de260fd28] nvme_rdma_create_ctrl at ffffffffc126919b
 #8 [ff61d23de260fd68] nvmf_dev_write at ffffffffc024f362
 #9 [ff61d23de260fe38] vfs_write at ffffffff827d5f25
    RIP: 00007fda7891d574  RSP: 00007ffe2ef06958  RFLAGS: 00000202
    RAX: ffffffffffffffda  RBX: 000055e8122a4d90  RCX: 00007fda7891d574
    RDX: 000000000000012b  RSI: 000055e8122a4d90  RDI: 0000000000000004
    RBP: 00007ffe2ef079c0   R8: 000000000000012b   R9: 000055e8122a4d90
    R10: 0000000000000000  R11: 0000000000000202  R12: 0000000000000004
    R13: 000055e8122923c0  R14: 000000000000012b  R15: 00007fda78a54500
    ORIG_RAX: 0000000000000001  CS: 0033  SS: 002b

This due to we have quiesced admi_q before cancel requests, but forgot
to unquiesce before destroy it, as a result we fail to drain the
pending requests, and hang on blk_mq_freeze_queue_wait() forever. Here
try to reuse nvme_rdma_teardown_admin_queue() to fix this issue and
simplify the code.

Fixes: 958dc1d ("nvme-rdma: add clean action for failed reconnection")
Reported-by: Yingfu.zhou <yingfu.zhou@shopee.com>
Signed-off-by: Chunguang.xu <chunguang.xu@shopee.com>
Signed-off-by: Yue.zhao <yue.zhao@shopee.com>
Reviewed-by: Christoph Hellwig <hch@lst.de>
Reviewed-by: Hannes Reinecke <hare@suse.de>
Signed-off-by: Keith Busch <kbusch@kernel.org>
Signed-off-by: Sasha Levin <sashal@kernel.org>
rbradford pushed a commit that referenced this pull request Jan 14, 2025
@acmel @gregkh
perf machine: Initialize machine->env to address a segfault
6234eda 
[ Upstream commit 88a6e2f ]

Its used from trace__run(), for the 'perf trace' live mode, i.e. its
strace-like, non-perf.data file processing mode, the most common one.

The trace__run() function will set trace->host using machine__new_host()
that is supposed to give a machine instance representing the running
machine, and since we'll use perf_env__arch_strerrno() to get the right
errno -> string table, we need to use machine->env, so initialize it in
machine__new_host().

Before the patch:

  (gdb) run trace --errno-summary -a sleep 1
  <SNIP>
   Summary of events:

   gvfs-afc-volume (3187), 2 events, 0.0%

     syscall            calls  errors  total       min       avg       max       stddev
                                       (msec)    (msec)    (msec)    (msec)        (%)
     --------------- --------  ------ -------- --------- --------- ---------     ------
     pselect6               1      0     0.000     0.000     0.000     0.000      0.00%

   GUsbEventThread (3519), 2 events, 0.0%

     syscall            calls  errors  total       min       avg       max       stddev
                                       (msec)    (msec)    (msec)    (msec)        (%)
     --------------- --------  ------ -------- --------- --------- ---------     ------
     poll                   1      0     0.000     0.000     0.000     0.000      0.00%
  <SNIP>
  Program received signal SIGSEGV, Segmentation fault.
  0x00000000005caba0 in perf_env__arch_strerrno (env=0x0, err=110) at util/env.c:478
  478		if (env->arch_strerrno == NULL)
  (gdb) bt
  #0  0x00000000005caba0 in perf_env__arch_strerrno (env=0x0, err=110) at util/env.c:478
  #1  0x00000000004b75d2 in thread__dump_stats (ttrace=0x14f58f0, trace=0x7fffffffa5b0, fp=0x7ffff6ff74e0 <_IO_2_1_stderr_>) at builtin-trace.c:4673
  #2  0x00000000004b78bf in trace__fprintf_thread (fp=0x7ffff6ff74e0 <_IO_2_1_stderr_>, thread=0x10fa0b0, trace=0x7fffffffa5b0) at builtin-trace.c:4708
  #3  0x00000000004b7ad9 in trace__fprintf_thread_summary (trace=0x7fffffffa5b0, fp=0x7ffff6ff74e0 <_IO_2_1_stderr_>) at builtin-trace.c:4747
  #4  0x00000000004b656e in trace__run (trace=0x7fffffffa5b0, argc=2, argv=0x7fffffffde60) at builtin-trace.c:4456
  #5  0x00000000004ba43e in cmd_trace (argc=2, argv=0x7fffffffde60) at builtin-trace.c:5487
  #6  0x00000000004c0414 in run_builtin (p=0xec3068 <commands+648>, argc=5, argv=0x7fffffffde60) at perf.c:351
  #7  0x00000000004c06bb in handle_internal_command (argc=5, argv=0x7fffffffde60) at perf.c:404
  #8  0x00000000004c0814 in run_argv (argcp=0x7fffffffdc4c, argv=0x7fffffffdc40) at perf.c:448
  #9  0x00000000004c0b5d in main (argc=5, argv=0x7fffffffde60) at perf.c:560
  (gdb)

After:

  root@number:~# perf trace -a --errno-summary sleep 1
  <SNIP>
     pw-data-loop (2685), 1410 events, 16.0%

     syscall            calls  errors  total       min       avg       max       stddev
                                       (msec)    (msec)    (msec)    (msec)        (%)
     --------------- --------  ------ -------- --------- --------- ---------     ------
     epoll_wait           188      0   983.428     0.000     5.231    15.595      8.68%
     ioctl                 94      0     0.811     0.004     0.009     0.016      2.82%
     read                 188      0     0.322     0.001     0.002     0.006      5.15%
     write                141      0     0.280     0.001     0.002     0.018      8.39%
     timerfd_settime       94      0     0.138     0.001     0.001     0.007      6.47%

   gnome-control-c (179406), 1848 events, 20.9%

     syscall            calls  errors  total       min       avg       max       stddev
                                       (msec)    (msec)    (msec)    (msec)        (%)
     --------------- --------  ------ -------- --------- --------- ---------     ------
     poll                 222      0   959.577     0.000     4.322    21.414     11.40%
     recvmsg              150      0     0.539     0.001     0.004     0.013      5.12%
     write                300      0     0.442     0.001     0.001     0.007      3.29%
     read                 150      0     0.183     0.001     0.001     0.009      5.53%
     getpid               102      0     0.101     0.000     0.001     0.008      7.82%

  root@number:~#

Fixes: 54373b5 ("perf env: Introduce perf_env__arch_strerrno()")
Reported-by: Veronika Molnarova <vmolnaro@redhat.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Acked-by: Veronika Molnarova <vmolnaro@redhat.com>
Acked-by: Michael Petlan <mpetlan@redhat.com>
Tested-by: Michael Petlan <mpetlan@redhat.com>
Link: https://lore.kernel.org/r/Z0XffUgNSv_9OjOi@x1
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Signed-off-by: Sasha Levin <sashal@kernel.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@rbradford rbradford rbradford approved these changes

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@jongwu @MrXinWang @rbradford @michael2012z