On Mon, Feb 03, 2025 at 07:10:25AM +0100, Stefano Brivio wrote:
> On Mon, 3 Feb 2025 14:11:10 +1100
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > On Fri, Jan 31, 2025 at 08:39:49PM +0100, Stefano Brivio wrote:
> > > Having every vhost-user message printed as part of debug output makes
> > > debugging anything else a bit complicated.
> > > 
> > > Signed-off-by: Stefano Brivio <sbrivio@redhat.com>  
> > 
> > I'm a little bit baffled by this.  You're changing to trace() a couple
> > of relatively rare messages
> 
> Well, "rare" is relative, if you're debugging state migration
> transfers. :) But...

Eh, I mean it's like 4ish events per migration.  And they are actually
related to the migration, rather than being unrelated async noise like
the stuff in vu_kick_cb().

Admittedly they are pretty verbose messages.

> > that I think belong in debug() category,
> 
> actually, yes, they're not so frequent. Probably we should improve on
> the reporting instead, because good luck finding your little message
> with transferred sizes in a rain of:
> 
>   ================ Vhost user message ================
> 
> we probably need a simple facility in vhost-user code allowing to
> start and continue some messages, so that if we need two lines here
> for "vhost-user: req %s (%d)\nflags: ..." we can do that easily.

Yeah, I'd be fine with making those vhost-user messages a little bit
less individually noisy.  Which presumably they were to make those
stand out against the other debug messages.  We perhaps don't want to
get into a shouting war with ourselves.

> As long as we're single-threaded, by the way, this could be simply
> two calls to debug().
> 
> > but *not* changing some things that definitely should be trace() -
> > such as the ones in vu_send_single() and vu_kick_cb().
> 
> Right, also noted for follow-ups.
> 
> > > ---
> > >  vhost_user.c | 12 ++++++------
> > >  1 file changed, 6 insertions(+), 6 deletions(-)
> > > 
> > > diff --git a/vhost_user.c b/vhost_user.c
> > > index 2dde405..1092387 100644
> > > --- a/vhost_user.c
> > > +++ b/vhost_user.c
> > > @@ -640,8 +640,8 @@ static bool vu_set_vring_num_exec(struct vu_dev *vdev,
> > >  	unsigned int idx = msg->payload.state.index;
> > >  	unsigned int num = msg->payload.state.num;
> > >  
> > > -	debug("State.index: %u", idx);
> > > -	debug("State.num:   %u", num);
> > > +	trace("State.index: %u", idx);
> > > +	trace("State.num:   %u", num);
> > >  	vdev->vq[idx].vring.num = num;
> > >  
> > >  	return false;
> > > @@ -1176,11 +1176,11 @@ void vu_control_handler(struct vu_dev *vdev, int fd, uint32_t events)
> > >  		vu_sock_reset(vdev);
> > >  		return;
> > >  	}
> > > -	debug("================ Vhost user message ================");
> > > -	debug("Request: %s (%d)", vu_request_to_string(msg.hdr.request),
> > > +	trace("================ Vhost user message ================");
> > > +	trace("Request: %s (%d)", vu_request_to_string(msg.hdr.request),
> > >  		msg.hdr.request);
> > > -	debug("Flags:   0x%x", msg.hdr.flags);
> > > -	debug("Size:    %u", msg.hdr.size);
> > > +	trace("Flags:   0x%x", msg.hdr.flags);
> > > +	trace("Size:    %u", msg.hdr.size);
> > >  
> > >  	need_reply = msg.hdr.flags & VHOST_USER_NEED_REPLY_MASK;
> 

-- 
David Gibson (he or they)	| I'll have my music baroque, and my code
david AT gibson.dropbear.id.au	| minimalist, thank you, not the other way
				| around.
http://www.ozlabs.org/~dgibson