Re: [Qemu-devel] [PATCH v2 1/5] qxl: switch qxl.c to trace-events

[Alon Levy]

On Mon, Mar 12, 2012 at 01:43:11PM +0200, Alon Levy wrote:
> On Mon, Mar 12, 2012 at 11:20:55AM +0100, Gerd Hoffmann wrote:
> > On 03/11/12 20:26, Alon Levy wrote:
> > > dprint is still used for qxl_init_common one time prints.
> > 
> > I think we shouldn't simply convert the dprintf's into trace-points.
> > 
> > We should look at each dprintf and check whenever it makes sense at all,
> > whenever it makes sense at that place before converting it over to a
> > tracepoint.

I'll also add qxl_spice_* trace points for the next patch. Does that
sound excessive? you could just trace the qxl_io_write to get the io
itself, or trace just qxl_spice_* to get the qxl<->spice interface, or
both (qxl_*).

> 
> I had two changes of heart about this. Initially I started mechanically
> converting, then I realized it only makes sense for recurring events,
> and things we want to see come out of the same output. But then I
> noticed a lot of existing users do use it for as verbose usage as we do
> (bh calls) and it is not meant as a stable interface to anyone - clearly
> something that should fit the developer and user, and if the subsystem
> changes then the events can change.
> 
> Bottom line I think having most of the dprints as trace_events makes
> sense, and we can use consistent naming to make enabling/disabling them
> easy for systemtap/stderr (with monitor trace-events command) easy.
> 
> I only left very few dprints.
> 
> > 
> > > @@ -409,7 +410,7 @@ static void interface_attach_worker(QXLInstance *sin, 
> > > QXLWorker *qxl_worker)
> > >  {
> > >      PCIQXLDevice *qxl = container_of(sin, PCIQXLDevice, ssd.qxl);
> > >  
> > > -    dprint(qxl, 1, "%s:\n", __FUNCTION__);
> > > +    trace_qxl_interface_attach_worker();
> > >      qxl->ssd.worker = qxl_worker;
> > >  }
> > 
> > For example: Do we really need that one?
> 
> I look at it the other way around - can it repeat? yes, it's a callback
> from the spice server which we don't control. does it serve the
> same purpose as the dprint? yes.
> 
> > 
> > > @@ -505,9 +506,10 @@ static int interface_get_command(QXLInstance *sin, 
> > > struct QXLCommandExt *ext)
> > >      QXLCommand *cmd;
> > >      int notify, ret;
> > >  
> > > +    trace_qxl_interface_get_command_enter(qxl_mode_to_string(qxl->mode));
> > > +
> > 
> > Why this?
> 
> Simplyfication of the dprints to avoid introducing an additional trace
> event. We had a dprint for level 1 for both VGA and other modes, so I
> moved it up. This trace is for each request from the server, as opposed
> to the _ret that is for each returned command (much less frequent).
> 
> > 
> > > -    dprint(qxl, 1, "%s: scheduling update_area_bh, #dirty %d\n",
> > > -           __func__, qxl->num_dirty_rects);
> > > +    
> > > trace_qxl_interface_update_area_complete_schedule_bh(qxl->num_dirty_rects);
> > 
> > I think it makes more sense to have the tracepoint in the bottom half
> > handler instead.
> 
> Why instead? I could add another one at the bottom half.
> 
> > 
> > >  static void qxl_hard_reset(PCIQXLDevice *d, int loadvm)
> > >  {
> > > -    dprint(d, 1, "%s: start%s\n", __FUNCTION__,
> > > -           loadvm ? " (loadvm)" : "");
> > > +    trace_qxl_hard_reset_enter(loadvm);
> > >  
> > >      qxl_spice_reset_cursor(d);
> > >      qxl_spice_reset_image_cache(d);
> > > @@ -934,7 +935,7 @@ static void qxl_hard_reset(PCIQXLDevice *d, int 
> > > loadvm)
> > >      qemu_spice_create_host_memslot(&d->ssd);
> > >      qxl_soft_reset(d);
> > >  
> > > -    dprint(d, 1, "%s: done\n", __FUNCTION__);
> > > +    trace_qxl_hard_reset_exit();
> > >  }
> > 
> > Do we need the exit tracepoint?
> 
> With systemtap I'd say the whole function could be traced, and that
> would mean both entry and exit. But you can't do that with the tracing
> framework, so this is the only way to have both.
> 
> If having both dprints makes no sense, I guess having both trace events
> makes none too.
> 
> > 
> > >  static void qxl_reset_memslots(PCIQXLDevice *d)
> > >  {
> > > -    dprint(d, 1, "%s:\n", __FUNCTION__);
> > > +    trace_qxl_reset_memslots();
> > >      qxl_spice_reset_memslots(d);
> > >      memset(&d->guest_slots, 0, sizeof(d->guest_slots));
> > >  }
> > 
> > Do we need that one?  qxl_hard_reset is the only caller of that function ...
> 
> Agree, I'll drop it.
> 
> But maybe I should add trace events for all the qxl_spice_* calls?
> 
> > 
> > > @@ -1216,8 +1213,8 @@ static void ioport_write(void *opaque, 
> > > target_phys_addr_t addr,
> > >          if (d->mode != QXL_MODE_VGA) {
> > >              break;
> > >          }
> > > -        dprint(d, 1, "%s: unexpected port 0x%x (%s) in vga mode\n",
> > > -            __func__, io_port, io_port_to_string(io_port));
> > > +        trace_qxl_io_unexpected_vga_mode(
> > > +            io_port, io_port_to_string(io_port));
> > 
> > We might want raise an error irq here, and have a tracepoint in
> > qxl_guest_bug() of course ...
> 
> ok, I think I can add the tracepoint for qxl_guest_bug. Raise an error
> irq I'll do in another patch.
> 
> > 
> > >      case QXL_IO_SET_MODE:
> > > -        dprint(d, 1, "QXL_SET_MODE %d\n", (int)val);
> > > +        trace_qxl_io_set_mode(val);
> > >          qxl_set_mode(d, val, 0);
> > 
> > Needed?  There is a tracepoint in qxl_set_mode() ...
> 
> But if qxl_set_mode can be called from multiple places it isn't
> equivalent.
> 
> > 
> > >      case QXL_IO_RESET:
> > > -        dprint(d, 1, "QXL_IO_RESET\n");
> > > +        trace_qxl_io_reset();
> > >          qxl_hard_reset(d, 0);
> > 
> > ... likewise ...
> 
> Same answer.
> 
> > 
> > >          break;
> > >      case QXL_IO_MEMSLOT_ADD:
> > > @@ -1337,7 +1334,7 @@ async_common:
> > >                            async);
> > >              goto cancel_async;
> > >          }
> > > -        dprint(d, 1, "QXL_IO_CREATE_PRIMARY async=%d\n", async);
> > > +        trace_qxl_io_create_primary(async);
> > >          d->guest_primary.surface = d->ram->create_surface;
> > >          qxl_create_guest_primary(d, 0, async);
> > 
> > ... here too ...
> 
> Ditto. The traceevents are named qxl_io_* on purpose, they are guest io
> triggered, there can be other calls to qxl_create_guest_primary.
> 
> Perhaps I'll have a single .. oh, you wrote the same thing below :)
> 
> > 
> > We might want to have a "trace_qxl_io_write(addr, val)" at the start of
> > the function, so we see all guest writes.  Traces for the actual ops (if
> > needed at all) are probably much better placed into the functions
> > executing the op as they can trace more details (i.e. qxl_set_mode has
> > the tracepoint *after* looking up the mode so we can stick the mode info
> > into the trace too).
> 
> Ok, that works.
> 
> > 
> > cheers,
> >   Gerd
> > 
>