Re: [Qemu-devel] [PATCH 2/2] target/ppc/kvm: Convert DPRINTF to traces

[Greg Kurz <groug@kaod.org>]

On Fri, 05 Apr 2019 10:12:42 -0300
"Murilo Opsfelder Araújo" <mopsfelder@gmail.com> wrote:

> Hi, Greg.
> 

Hi Murilo,

> Greg Kurz <groug@kaod.org> writes:
> 
> > Signed-off-by: Greg Kurz <groug@kaod.org>
> > ---
> >  target/ppc/kvm.c        |   68 +++++++++++++++++++----------------------------
> >  target/ppc/trace-events |   25 +++++++++++++++++
> >  2 files changed, 52 insertions(+), 41 deletions(-)
> >
> > diff --git a/target/ppc/kvm.c b/target/ppc/kvm.c
> > index 2427c8ee13ae..3a11d2e1060c 100644
> > --- a/target/ppc/kvm.c
> > +++ b/target/ppc/kvm.c
> > @@ -49,16 +49,6 @@
> >  #include "elf.h"
> >  #include "sysemu/kvm_int.h"
> >
> > -//#define DEBUG_KVM
> > -
> > -#ifdef DEBUG_KVM
> > -#define DPRINTF(fmt, ...) \
> > -    do { fprintf(stderr, fmt, ## __VA_ARGS__); } while (0)
> > -#else
> > -#define DPRINTF(fmt, ...) \
> > -    do { } while (0)
> > -#endif
> > -
> >  #define PROC_DEVTREE_CPU      "/proc/device-tree/cpus/"
> >
> >  const KVMCapabilityInfo kvm_arch_required_capabilities[] = {
> > @@ -626,7 +616,7 @@ static int kvm_put_fp(CPUState *cs)
> >          reg.addr = (uintptr_t)&fpscr;
> >          ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >          if (ret < 0) {
> > -            DPRINTF("Unable to set FPSCR to KVM: %s\n", strerror(errno));
> > +            trace_kvm_failed_fpscr_set(strerror(errno));
> >              return ret;
> >          }
> >
> > @@ -647,8 +637,8 @@ static int kvm_put_fp(CPUState *cs)
> >
> >              ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >              if (ret < 0) {
> > -                DPRINTF("Unable to set %s%d to KVM: %s\n", vsx ? "VSR" : "FPR",
> > -                        i, strerror(errno));
> > +                trace_kvm_failed_fp_set(vsx ? "VSR" : "FPR", i,
> > +                                        strerror(errno));
> >                  return ret;
> >              }
> >          }
> > @@ -659,7 +649,7 @@ static int kvm_put_fp(CPUState *cs)
> >          reg.addr = (uintptr_t)&env->vscr;
> >          ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >          if (ret < 0) {
> > -            DPRINTF("Unable to set VSCR to KVM: %s\n", strerror(errno));
> > +            trace_kvm_failed_vscr_set(strerror(errno));
> >              return ret;
> >          }
> >
> > @@ -668,7 +658,7 @@ static int kvm_put_fp(CPUState *cs)
> >              reg.addr = (uintptr_t)cpu_avr_ptr(env, i);
> >              ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >              if (ret < 0) {
> > -                DPRINTF("Unable to set VR%d to KVM: %s\n", i, strerror(errno));
> > +                trace_kvm_failed_vr_set(i, strerror(errno));
> >                  return ret;
> >              }
> >          }
> > @@ -693,7 +683,7 @@ static int kvm_get_fp(CPUState *cs)
> >          reg.addr = (uintptr_t)&fpscr;
> >          ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >          if (ret < 0) {
> > -            DPRINTF("Unable to get FPSCR from KVM: %s\n", strerror(errno));
> > +            trace_kvm_failed_fpscr_get(strerror(errno));
> >              return ret;
> >          } else {
> >              env->fpscr = fpscr;
> > @@ -709,8 +699,8 @@ static int kvm_get_fp(CPUState *cs)
> >
> >              ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >              if (ret < 0) {
> > -                DPRINTF("Unable to get %s%d from KVM: %s\n",
> > -                        vsx ? "VSR" : "FPR", i, strerror(errno));
> > +                trace_kvm_failed_fp_get(vsx ? "VSR" : "FPR", i,
> > +                                        strerror(errno));
> >                  return ret;
> >              } else {
> >  #ifdef HOST_WORDS_BIGENDIAN
> > @@ -733,7 +723,7 @@ static int kvm_get_fp(CPUState *cs)
> >          reg.addr = (uintptr_t)&env->vscr;
> >          ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >          if (ret < 0) {
> > -            DPRINTF("Unable to get VSCR from KVM: %s\n", strerror(errno));
> > +            trace_kvm_failed_vscr_get(strerror(errno));
> >              return ret;
> >          }
> >
> > @@ -742,8 +732,7 @@ static int kvm_get_fp(CPUState *cs)
> >              reg.addr = (uintptr_t)cpu_avr_ptr(env, i);
> >              ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >              if (ret < 0) {
> > -                DPRINTF("Unable to get VR%d from KVM: %s\n",
> > -                        i, strerror(errno));
> > +                trace_kvm_failed_vr_get(i, strerror(errno));
> >                  return ret;
> >              }
> >          }
> > @@ -764,7 +753,7 @@ static int kvm_get_vpa(CPUState *cs)
> >      reg.addr = (uintptr_t)&spapr_cpu->vpa_addr;
> >      ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >      if (ret < 0) {
> > -        DPRINTF("Unable to get VPA address from KVM: %s\n", strerror(errno));
> > +        trace_kvm_failed_vpa_addr_get(strerror(errno));
> >          return ret;
> >      }
> >
> > @@ -774,8 +763,7 @@ static int kvm_get_vpa(CPUState *cs)
> >      reg.addr = (uintptr_t)&spapr_cpu->slb_shadow_addr;
> >      ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >      if (ret < 0) {
> > -        DPRINTF("Unable to get SLB shadow state from KVM: %s\n",
> > -                strerror(errno));
> > +        trace_kvm_failed_slb_get(strerror(errno));
> >          return ret;
> >      }
> >
> > @@ -785,8 +773,7 @@ static int kvm_get_vpa(CPUState *cs)
> >      reg.addr = (uintptr_t)&spapr_cpu->dtl_addr;
> >      ret = kvm_vcpu_ioctl(cs, KVM_GET_ONE_REG, &reg);
> >      if (ret < 0) {
> > -        DPRINTF("Unable to get dispatch trace log state from KVM: %s\n",
> > -                strerror(errno));
> > +        trace_kvm_failed_dtl_get(strerror(errno));
> >          return ret;
> >      }
> >
> > @@ -812,7 +799,7 @@ static int kvm_put_vpa(CPUState *cs)
> >          reg.addr = (uintptr_t)&spapr_cpu->vpa_addr;
> >          ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >          if (ret < 0) {
> > -            DPRINTF("Unable to set VPA address to KVM: %s\n", strerror(errno));
> > +            trace_kvm_failed_vpa_addr_set(strerror(errno));
> >              return ret;
> >          }
> >      }
> > @@ -823,7 +810,7 @@ static int kvm_put_vpa(CPUState *cs)
> >      reg.addr = (uintptr_t)&spapr_cpu->slb_shadow_addr;
> >      ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >      if (ret < 0) {
> > -        DPRINTF("Unable to set SLB shadow state to KVM: %s\n", strerror(errno));
> > +        trace_kvm_failed_slb_set(strerror(errno));
> >          return ret;
> >      }
> >
> > @@ -833,8 +820,7 @@ static int kvm_put_vpa(CPUState *cs)
> >      reg.addr = (uintptr_t)&spapr_cpu->dtl_addr;
> >      ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >      if (ret < 0) {
> > -        DPRINTF("Unable to set dispatch trace log state to KVM: %s\n",
> > -                strerror(errno));
> > +        trace_kvm_failed_dtl_set(strerror(errno));
> >          return ret;
> >      }
> >
> > @@ -843,7 +829,7 @@ static int kvm_put_vpa(CPUState *cs)
> >          reg.addr = (uintptr_t)&spapr_cpu->vpa_addr;
> >          ret = kvm_vcpu_ioctl(cs, KVM_SET_ONE_REG, &reg);
> >          if (ret < 0) {
> > -            DPRINTF("Unable to set VPA address to KVM: %s\n", strerror(errno));
> > +            trace_kvm_failed_null_vpa_addr_set(strerror(errno));
> >              return ret;
> >          }
> >      }
> > @@ -996,7 +982,7 @@ int kvm_arch_put_registers(CPUState *cs, int level)
> >
> >          if (cap_papr) {
> >              if (kvm_put_vpa(cs) < 0) {
> > -                DPRINTF("Warning: Unable to set VPA information to KVM\n");
> > +                trace_kvm_failed_put_vpa();
> >              }
> >          }
> >
> > @@ -1296,7 +1282,7 @@ int kvm_arch_get_registers(CPUState *cs)
> >
> >          if (cap_papr) {
> >              if (kvm_get_vpa(cs) < 0) {
> > -                DPRINTF("Warning: Unable to get VPA information from KVM\n");
> > +                trace_kvm_failed_get_vpa();
> >              }
> >          }
> >
> > @@ -1352,7 +1338,7 @@ void kvm_arch_pre_run(CPUState *cs, struct kvm_run *run)
> >           */
> >          irq = KVM_INTERRUPT_SET;
> >
> > -        DPRINTF("injected interrupt %d\n", irq);
> > +        trace_kvm_injected_interrupt(irq);
> >          r = kvm_vcpu_ioctl(cs, KVM_INTERRUPT, &irq);
> >          if (r < 0) {
> >              printf("cpu %d fail inject %x\n", cs->cpu_index, irq);
> > @@ -1697,20 +1683,20 @@ int kvm_arch_handle_exit(CPUState *cs, struct kvm_run *run)
> >      switch (run->exit_reason) {
> >      case KVM_EXIT_DCR:
> >          if (run->dcr.is_write) {
> > -            DPRINTF("handle dcr write\n");
> > +            trace_kvm_handle_dcr_write();
> >              ret = kvmppc_handle_dcr_write(env, run->dcr.dcrn, run->dcr.data);
> >          } else {
> > -            DPRINTF("handle dcr read\n");
> > +            trace_kvm_handle_drc_read();
> >              ret = kvmppc_handle_dcr_read(env, run->dcr.dcrn, &run->dcr.data);
> >          }
> >          break;
> >      case KVM_EXIT_HLT:
> > -        DPRINTF("handle halt\n");
> > +        trace_kvm_handle_halt();
> >          ret = kvmppc_handle_halt(cpu);
> >          break;
> >  #if defined(TARGET_PPC64)
> >      case KVM_EXIT_PAPR_HCALL:
> > -        DPRINTF("handle PAPR hypercall\n");
> > +        trace_kvm_handle_papr_hcall();
> >          run->papr_hcall.ret = spapr_hypercall(cpu,
> >                                                run->papr_hcall.nr,
> >                                                run->papr_hcall.args);
> > @@ -1718,18 +1704,18 @@ int kvm_arch_handle_exit(CPUState *cs, struct kvm_run *run)
> >          break;
> >  #endif
> >      case KVM_EXIT_EPR:
> > -        DPRINTF("handle epr\n");
> > +        trace_kvm_handle_epr();
> >          run->epr.epr = ldl_phys(cs->as, env->mpic_iack);
> >          ret = 0;
> >          break;
> >      case KVM_EXIT_WATCHDOG:
> > -        DPRINTF("handle watchdog expiry\n");
> > +        trace_kvm_handle_watchdog_expiry();
> >          watchdog_perform_action();
> >          ret = 0;
> >          break;
> >
> >      case KVM_EXIT_DEBUG:
> > -        DPRINTF("handle debug exception\n");
> > +        trace_kvm_handle_debug_exception();
> >          if (kvm_handle_debug(cpu, run)) {
> >              ret = EXCP_DEBUG;
> >              break;
> > diff --git a/target/ppc/trace-events b/target/ppc/trace-events
> > index ed4d57c6d9c1..7b3cfe11fdfe 100644
> > --- a/target/ppc/trace-events
> > +++ b/target/ppc/trace-events
> > @@ -3,3 +3,28 @@
> >  # kvm.c
> >  kvm_failed_spr_set(int spr, const char *msg) "Warning: Unable to set SPR %d to KVM: %s"
> >  kvm_failed_spr_get(int spr, const char *msg) "Warning: Unable to retrieve SPR %d from KVM: %s"
> > +kvm_failed_fpscr_set(const char *msg) "Unable to set FPSCR to KVM: %s"
> > +kvm_failed_fp_set(const char *fpname, int fpnum, const char *msg) "Unable to set %s%d to KVM: %s"
> > +kvm_failed_vscr_set(const char *msg) "Unable to set VSCR to KVM: %s"
> > +kvm_failed_vr_set(int vr, const char *msg) "Unable to set VR%d to KVM: %s"
> > +kvm_failed_fpscr_get(const char *msg) "Unable to get FPSCR from KVM: %s"
> > +kvm_failed_fp_get(const char *fpname, int fpnum, const char *msg) "Unable to get %s%d from KVM: %s"
> > +kvm_failed_vscr_get(const char *msg) "Unable to get VSCR from KVM: %s"
> > +kvm_failed_vr_get(int vr, const char *msg) "Unable to get VR%d from KVM: %s"
> > +kvm_failed_vpa_addr_get(const char *msg) "Unable to get VPA address from KVM: %s"
> > +kvm_failed_slb_get(const char *msg) "Unable to get SLB shadow state from KVM: %s"
> > +kvm_failed_dtl_get(const char *msg) "Unable to get dispatch trace log state from KVM: %s"
> > +kvm_failed_vpa_addr_set(const char *msg) "Unable to set VPA address to KVM: %s"
> > +kvm_failed_slb_set(const char *msg) "Unable to set SLB shadow state to KVM: %s"
> > +kvm_failed_dtl_set(const char *msg) "Unable to set dispatch trace log state to KVM: %s"
> > +kvm_failed_null_vpa_addr_set(const char *msg) "Unable to set VPA address to KVM: %s"
> > +kvm_failed_put_vpa(void) "Warning: Unable to set VPA information to KVM"
> > +kvm_failed_get_vpa(void) "Warning: Unable to get VPA information from KVM"  
> 
> Some messages have "Warning:" and some don't.
> 

Yeah I saw that.

> Since these traces indicate some kind of failure, do you think adding
> the warning prefix would be welcome?  Having it also facilitates when
> searching logs.
> 

FWIW the ones with "Warning:" are actual warnings, ie. the code just prints a
message and continues execution without propagating the error. The other ones
are on an error propagation path... so I'm not sure if it helps that much
since some code will eventually handle the error.

> Murilo
> 
> > +kvm_injected_interrupt(int irq) "injected interrupt %d"
> > +kvm_handle_dcr_write(void) "handle dcr write"
> > +kvm_handle_drc_read(void) "handle dcr read"
> > +kvm_handle_halt(void) "handle halt"
> > +kvm_handle_papr_hcall(void) "handle PAPR hypercall"
> > +kvm_handle_epr(void) "handle epr"
> > +kvm_handle_watchdog_expiry(void) "handle watchdog expiry"
> > +kvm_handle_debug_exception(void) "handle debug exception"