hw/ppc/ppc.c | 5 +++++ target/ppc/cpu.h | 1 + target/ppc/cpu_init.c | 5 +++-- 3 files changed, 9 insertions(+), 2 deletions(-)
When debugging issues in KVM guests, it is sometimes helpful to have a
unified trace log of both guest and host to see where things are going
wrong. Expose the TB (timebase) offset through QEMU monitor to enable
capturing of unified log.
The below steps can be then used to get a unified log:
1. In host
trace-cmd record -e kvm_hv:kvm_guest_enter -e kvm_hv:kvm_guest_exit \
-C ppc-tb -o trace_host.dat
2. In guest
trace-cmd record -e powerpc:hcall_entry -e powerpc:hcall_exit -C ppc-tb \
--ts-offset <TB offset from QEMU monitor> -o trace_guest.dat
NOTE: The TB offset would be reported as a negative number in QEMU
monitor. For this step, the minus sign must be ignored.
3. Transfer the guest logs to the host with scp/rsync
4. Unify the logs
trace-cmd report -i trace_host.dat -i trace_guest.dat > combined_log
Signed-off-by: Gautam Menghani <gautam@linux.ibm.com>
---
v1 -> v2:
1. Remove extra deref and ref code (Vaibhav)
2. Fix the QEMU monitor output to add the new field at the end (Vaibhav)
hw/ppc/ppc.c | 5 +++++
target/ppc/cpu.h | 1 +
target/ppc/cpu_init.c | 5 +++--
3 files changed, 9 insertions(+), 2 deletions(-)
diff --git a/hw/ppc/ppc.c b/hw/ppc/ppc.c
index a512d4fa64..b123b4cc1c 100644
--- a/hw/ppc/ppc.c
+++ b/hw/ppc/ppc.c
@@ -515,6 +515,11 @@ uint64_t cpu_ppc_get_tb(ppc_tb_t *tb_env, uint64_t vmclk, int64_t tb_offset)
return ns_to_tb(tb_env->tb_freq, vmclk) + tb_offset;
}
+int64_t cpu_ppc_load_tb_offset(CPUPPCState *env)
+{
+ return env->tb_env->tb_offset;
+}
+
uint64_t cpu_ppc_load_tbl (CPUPPCState *env)
{
ppc_tb_t *tb_env = env->tb_env;
diff --git a/target/ppc/cpu.h b/target/ppc/cpu.h
index 057c54bbb8..cbd5964b1a 100644
--- a/target/ppc/cpu.h
+++ b/target/ppc/cpu.h
@@ -1693,6 +1693,7 @@ void cpu_ppc_store_hdecr(CPUPPCState *env, target_ulong value);
void cpu_ppc_store_tbu40(CPUPPCState *env, uint64_t value);
uint64_t cpu_ppc_load_purr(CPUPPCState *env);
void cpu_ppc_store_purr(CPUPPCState *env, uint64_t value);
+int64_t cpu_ppc_load_tb_offset(CPUPPCState *env);
#if !defined(CONFIG_USER_ONLY)
target_ulong load_40x_pit(CPUPPCState *env);
void store_40x_pit(CPUPPCState *env, target_ulong val);
diff --git a/target/ppc/cpu_init.c b/target/ppc/cpu_init.c
index a02187ce5a..8cab5e12b6 100644
--- a/target/ppc/cpu_init.c
+++ b/target/ppc/cpu_init.c
@@ -7620,8 +7620,9 @@ void ppc_cpu_dump_state(CPUState *cs, FILE *f, int flags)
#if !defined(CONFIG_USER_ONLY)
if (env->tb_env) {
qemu_fprintf(f, "TB %08" PRIu32 " %08" PRIu64
- " DECR " TARGET_FMT_lu "\n", cpu_ppc_load_tbu(env),
- cpu_ppc_load_tbl(env), cpu_ppc_load_decr(env));
+ " DECR " TARGET_FMT_lu " TB_OFFSET %016" PRId64 "\n",
+ cpu_ppc_load_tbu(env), cpu_ppc_load_tbl(env),
+ cpu_ppc_load_decr(env), cpu_ppc_load_tb_offset(env));
}
#else
qemu_fprintf(f, "TB %08" PRIu32 " %08" PRIu64 "\n", cpu_ppc_load_tbu(env),
--
2.54.0
- Host: SLES 16.1 (ppc64le, Power11)
- Kernel: 6.12.0-160099.38-default
- QEMU: built from latest master (commit b3ea565608)
- Guest: avocado-vt-vm1 (ppc64 KVM guest)
—logs—
TB offset visible in QEMU monitor:
# virsh qemu-monitor-command avocado-vt-vm1 --hmp "info registers" | grep TB_OFFSET
TB 00000000 00000000 DECR 0 TB_OFFSET -916489431416832
On Host :
qemu # trace-cmd record -e kvm_hv:kvm_guest_enter -e kvm_hv:kvm_guest_exit
Hit Ctrl^C to stop recording
^CCPU0 data recorded at offset=0x140000
2728 bytes in size (65536 uncompressed)
CPU1 data recorded at offset=0x150000
187 bytes in size (65536 uncompressed)
CPU2 data recorded at offset=0x160000
7084 bytes in size (65536 uncompressed)
CPU3 data recorded at offset=0x170000
0 bytes in size (0 uncompressed)
.
.
.
CPU14 data recorded at offset=0x1e0000
0 bytes in size (0 uncompressed)
CPU15 data recorded at offset=0x1e0000
42586 bytes in size (524288 uncompressed)
On Guest :
# trace-cmd record -e powerpc:hcall_entry -e powerpc:hcall_exit -C ppc-tb --ts-offset 916489431416832 -o trace_guest.dat
Hit Ctrl^C to stop recording
^CCPU0 data recorded at offset=0x130000
186 bytes in size (65536 uncompressed)
CPU1 data recorded at offset=0x140000
522 bytes in size (65536 uncompressed)
CPU2 data recorded at offset=0x150000
95 bytes in size (65536 uncompressed)
CPU3 data recorded at offset=0x160000
111 bytes in size (65536 uncompressed)
qemu # head -10 /root/combined_log
trace_host.dat: cpus=16
trace_guest.dat: cpus=4
trace_host.dat: CPU 1/KVM-596247 [000] d..1.916674455351586: kvm_guest_enter: VCPU 1: pc=0xc0000000001b60e8 pexcp=0x8000 ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] .....916674455369430: kvm_guest_exit: VCPU 1: trap=H_DATA_STORAGE pc=0xc008000001c6070c msr=0x800000000280a033, ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] d..1.916674455373152: kvm_guest_enter: VCPU 1: pc=0xc008000001c60710 pexcp=0x0 ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] .....916674455378631: kvm_guest_exit: VCPU 1: trap=H_DATA_STORAGE pc=0xc008000001c6070c msr=0x800000000280a033, ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] d..1.916674455380902: kvm_guest_enter: VCPU 1: pc=0xc008000001c60710 pexcp=0x0 ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] .....916674455386279: kvm_guest_exit: VCPU 1: trap=H_DATA_STORAGE pc=0xc008000001c6070c msr=0x800000000280a033, ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] d..1.916674455388450: kvm_guest_enter: VCPU 1: pc=0xc008000001c60710 pexcp=0x0 ceded=0
trace_host.dat: CPU 1/KVM-596247 [000] .....916674455393602: kvm_guest_exit: VCPU 1: trap=H_DATA_STORAGE pc=0xc008000001c60f4c msr=0x800000000280a033, ceded=0
Tested-by: Sneh Shikha Yadav <syadav@linux.ibm.com>
Gautam Menghani <gautam@linux.ibm.com> writes:
> When debugging issues in KVM guests, it is sometimes helpful to have a
> unified trace log of both guest and host to see where things are going
> wrong. Expose the TB (timebase) offset through QEMU monitor to enable
> capturing of unified log.
>
> The below steps can be then used to get a unified log:
> 1. In host
> trace-cmd record -e kvm_hv:kvm_guest_enter -e kvm_hv:kvm_guest_exit \
> -C ppc-tb -o trace_host.dat
>
> 2. In guest
> trace-cmd record -e powerpc:hcall_entry -e powerpc:hcall_exit -C ppc-tb \
> --ts-offset <TB offset from QEMU monitor> -o trace_guest.dat
>
> NOTE: The TB offset would be reported as a negative number in QEMU
> monitor. For this step, the minus sign must be ignored.
>
> 3. Transfer the guest logs to the host with scp/rsync
>
> 4. Unify the logs
> trace-cmd report -i trace_host.dat -i trace_guest.dat > combined_log
>
> Signed-off-by: Gautam Menghani <gautam@linux.ibm.com>
> ---
> v1 -> v2:
> 1. Remove extra deref and ref code (Vaibhav)
> 2. Fix the QEMU monitor output to add the new field at the end (Vaibhav)
Thanks Gautam from addressing V1 review comments. With this feel free to
add
Reviewed-by: Vaibhav Jain<vaibhav@linux.ibm.com>
>
> hw/ppc/ppc.c | 5 +++++
> target/ppc/cpu.h | 1 +
> target/ppc/cpu_init.c | 5 +++--
> 3 files changed, 9 insertions(+), 2 deletions(-)
>
> diff --git a/hw/ppc/ppc.c b/hw/ppc/ppc.c
> index a512d4fa64..b123b4cc1c 100644
> --- a/hw/ppc/ppc.c
> +++ b/hw/ppc/ppc.c
> @@ -515,6 +515,11 @@ uint64_t cpu_ppc_get_tb(ppc_tb_t *tb_env, uint64_t vmclk, int64_t tb_offset)
> return ns_to_tb(tb_env->tb_freq, vmclk) + tb_offset;
> }
>
> +int64_t cpu_ppc_load_tb_offset(CPUPPCState *env)
> +{
> + return env->tb_env->tb_offset;
> +}
> +
> uint64_t cpu_ppc_load_tbl (CPUPPCState *env)
> {
> ppc_tb_t *tb_env = env->tb_env;
> diff --git a/target/ppc/cpu.h b/target/ppc/cpu.h
> index 057c54bbb8..cbd5964b1a 100644
> --- a/target/ppc/cpu.h
> +++ b/target/ppc/cpu.h
> @@ -1693,6 +1693,7 @@ void cpu_ppc_store_hdecr(CPUPPCState *env, target_ulong value);
> void cpu_ppc_store_tbu40(CPUPPCState *env, uint64_t value);
> uint64_t cpu_ppc_load_purr(CPUPPCState *env);
> void cpu_ppc_store_purr(CPUPPCState *env, uint64_t value);
> +int64_t cpu_ppc_load_tb_offset(CPUPPCState *env);
> #if !defined(CONFIG_USER_ONLY)
> target_ulong load_40x_pit(CPUPPCState *env);
> void store_40x_pit(CPUPPCState *env, target_ulong val);
> diff --git a/target/ppc/cpu_init.c b/target/ppc/cpu_init.c
> index a02187ce5a..8cab5e12b6 100644
> --- a/target/ppc/cpu_init.c
> +++ b/target/ppc/cpu_init.c
> @@ -7620,8 +7620,9 @@ void ppc_cpu_dump_state(CPUState *cs, FILE *f, int flags)
> #if !defined(CONFIG_USER_ONLY)
> if (env->tb_env) {
> qemu_fprintf(f, "TB %08" PRIu32 " %08" PRIu64
> - " DECR " TARGET_FMT_lu "\n", cpu_ppc_load_tbu(env),
> - cpu_ppc_load_tbl(env), cpu_ppc_load_decr(env));
> + " DECR " TARGET_FMT_lu " TB_OFFSET %016" PRId64 "\n",
> + cpu_ppc_load_tbu(env), cpu_ppc_load_tbl(env),
> + cpu_ppc_load_decr(env), cpu_ppc_load_tb_offset(env));
> }
> #else
> qemu_fprintf(f, "TB %08" PRIu32 " %08" PRIu64 "\n", cpu_ppc_load_tbu(env),
> --
> 2.54.0
>
--
Cheers
~ Vaibhav
Hi Gautam,
Thanks for the patch. Please find my review comments below:
On 2026/06/26 03:05 PM, Gautam Menghani wrote:
> When debugging issues in KVM guests, it is sometimes helpful to have a
> unified trace log of both guest and host to see where things are going
> wrong. Expose the TB (timebase) offset through QEMU monitor to enable
> capturing of unified log.
Thanks for working on it. This is useful.
>
> The below steps can be then used to get a unified log:
> 1. In host
> trace-cmd record -e kvm_hv:kvm_guest_enter -e kvm_hv:kvm_guest_exit \
> -C ppc-tb -o trace_host.dat
>
> 2. In guest
> trace-cmd record -e powerpc:hcall_entry -e powerpc:hcall_exit -C ppc-tb \
> --ts-offset <TB offset from QEMU monitor> -o trace_guest.dat
>
> NOTE: The TB offset would be reported as a negative number in QEMU
> monitor. For this step, the minus sign must be ignored.
>
> 3. Transfer the guest logs to the host with scp/rsync
>
> 4. Unify the logs
> trace-cmd report -i trace_host.dat -i trace_guest.dat > combined_log
>
> Signed-off-by: Gautam Menghani <gautam@linux.ibm.com>
> ---
> v1 -> v2:
> 1. Remove extra deref and ref code (Vaibhav)
> 2. Fix the QEMU monitor output to add the new field at the end (Vaibhav)
>
> hw/ppc/ppc.c | 5 +++++
> target/ppc/cpu.h | 1 +
> target/ppc/cpu_init.c | 5 +++--
> 3 files changed, 9 insertions(+), 2 deletions(-)
>
> diff --git a/hw/ppc/ppc.c b/hw/ppc/ppc.c
> index a512d4fa64..b123b4cc1c 100644
> --- a/hw/ppc/ppc.c
> +++ b/hw/ppc/ppc.c
> @@ -515,6 +515,11 @@ uint64_t cpu_ppc_get_tb(ppc_tb_t *tb_env, uint64_t vmclk, int64_t tb_offset)
> return ns_to_tb(tb_env->tb_freq, vmclk) + tb_offset;
> }
>
> +int64_t cpu_ppc_load_tb_offset(CPUPPCState *env)
> +{
> + return env->tb_env->tb_offset;
> +}
> +
> uint64_t cpu_ppc_load_tbl (CPUPPCState *env)
> {
> ppc_tb_t *tb_env = env->tb_env;
> diff --git a/target/ppc/cpu.h b/target/ppc/cpu.h
> index 057c54bbb8..cbd5964b1a 100644
> --- a/target/ppc/cpu.h
> +++ b/target/ppc/cpu.h
> @@ -1693,6 +1693,7 @@ void cpu_ppc_store_hdecr(CPUPPCState *env, target_ulong value);
> void cpu_ppc_store_tbu40(CPUPPCState *env, uint64_t value);
> uint64_t cpu_ppc_load_purr(CPUPPCState *env);
> void cpu_ppc_store_purr(CPUPPCState *env, uint64_t value);
> +int64_t cpu_ppc_load_tb_offset(CPUPPCState *env);
> #if !defined(CONFIG_USER_ONLY)
> target_ulong load_40x_pit(CPUPPCState *env);
> void store_40x_pit(CPUPPCState *env, target_ulong val);
> diff --git a/target/ppc/cpu_init.c b/target/ppc/cpu_init.c
> index a02187ce5a..8cab5e12b6 100644
> --- a/target/ppc/cpu_init.c
> +++ b/target/ppc/cpu_init.c
> @@ -7620,8 +7620,9 @@ void ppc_cpu_dump_state(CPUState *cs, FILE *f, int flags)
> #if !defined(CONFIG_USER_ONLY)
> if (env->tb_env) {
> qemu_fprintf(f, "TB %08" PRIu32 " %08" PRIu64
> - " DECR " TARGET_FMT_lu "\n", cpu_ppc_load_tbu(env),
> - cpu_ppc_load_tbl(env), cpu_ppc_load_decr(env));
> + " DECR " TARGET_FMT_lu " TB_OFFSET %016" PRId64 "\n",
> + cpu_ppc_load_tbu(env), cpu_ppc_load_tbl(env),
> + cpu_ppc_load_decr(env), cpu_ppc_load_tb_offset(env));
I tested the patch on P10 LPAR and host and the patch works as expected.
Without patch:
--------------
[...]
TB 00000000 00000000 DECR 0
With patch:
-----------
[...]
TB 00000000 00000000 DECR 0 TB_OFFSET -5980196012294144
Hence,
Tested-by: Amit Machhiwal <amachhiw@linux.ibm.com>
Minor observation: the TB_OFFSET field will always print
0000000000000000 for a TCG guest — tb_offset is zero-initialised in
cpu_ppc_tb_init() and never updated as I think in the TCG path
QEMU_CLOCK_VIRTUAL starts from 0 at VM start, requiring no offset
correction.
TB 00000113 488874479567 DECR 1265321 TB_OFFSET 0000000000000000
The commit message correctly scopes this to KVM guests, so this isn't a
bug. But since TB_OFFSET appears unconditionally in info registers for
all guests, a user running a TCG guest might find the zero value
confusing. Worth either guarding it with kvm_enabled() or adding a brief
code comment and as well as in the commit log noting it is only
meaningful under KVM.
With above change, please free to add:
Reviewed-by: Amit Machhiwal <amachhiw@linux.ibm.com>
Thanks,
Amit
> }
> #else
> qemu_fprintf(f, "TB %08" PRIu32 " %08" PRIu64 "\n", cpu_ppc_load_tbu(env),
> --
> 2.54.0
>
>
© 2016 - 2026 Red Hat, Inc.