Re: [Qemu-devel] [PATCH v4 17/47] ivshmem: improve debug messages

[Claudio Fontana]

On 29.09.2015 15:12, Marc-André Lureau wrote:
> 
> 
> ----- Original Message -----
>> On 24.09.2015 13:37, address@hidden wrote:
>>> From: Marc-André Lureau <address@hidden>
>>>
>>> Some misc improvements to ivshmem debug.
>>>
>>> Signed-off-by: Marc-André Lureau <address@hidden>
>>> ---
>>>  hw/misc/ivshmem.c | 10 +++++++---
>>>  1 file changed, 7 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/hw/misc/ivshmem.c b/hw/misc/ivshmem.c
>>> index c4c130d..71a71fc 100644
>>> --- a/hw/misc/ivshmem.c
>>> +++ b/hw/misc/ivshmem.c
>>> @@ -208,10 +208,13 @@ static void ivshmem_io_write(void *opaque, hwaddr
>>> addr,
>>>              if (vector < s->peers[dest].nb_eventfds) {
>>>                  IVSHMEM_DPRINTF("Notifying VM %d on vector %d\n", dest,
>>>                  vector);
>>>                  event_notifier_set(&s->peers[dest].eventfds[vector]);
>>> +            } else {
>>> +                IVSHMEM_DPRINTF("Invalid destination vector %d on VM
>>> %d\n",
>>> +                                vector, dest);
>>>              }
>>>              break;
>>>          default:
>>> -            IVSHMEM_DPRINTF("Invalid VM Doorbell VM %d\n", dest);
>>> +            IVSHMEM_DPRINTF("Unhandled write " TARGET_FMT_plx "\n", addr);
>>>      }
>>>  }
>>>  
>>> @@ -263,9 +266,9 @@ static void ivshmem_receive(void *opaque, const uint8_t
>>> *buf, int size)
>>>  {
>>>      IVShmemState *s = opaque;
>>>  
>>> -    ivshmem_IntrStatus_write(s, *buf);
>>> +    IVSHMEM_DPRINTF("ivshmem_receive 0x%02x size: %d\n", *buf, size);
>>>  
>>> -    IVSHMEM_DPRINTF("ivshmem_receive 0x%02x\n", *buf);
>>> +    ivshmem_IntrStatus_write(s, *buf);
>>>  }
>>
>> I may understand how this went here, so these debug messages are clearly
>> specific about this particular function.
>> here you have "ivshmem_receive". Do you want to put () to help someone
>> getting these messages after enabling debug to understand that he should
>> look up this function?
> 
> sure, notice it was there before without ()
> 
>> In the other messages though you (and the previous code) have been less
>> function-specific in the message.
> 
> imho this kind of debug messages should just give enough context to 
> understand and locate them. It's not important whether or not they have the 
> function name.
> 
> 
>>>  
>>>  static int ivshmem_can_receive(void * opaque)
>>> @@ -592,6 +595,7 @@ static void ivshmem_use_msix(IVShmemState * s)
>>>      PCIDevice *d = PCI_DEVICE(s);
>>>      int i;
>>>  
>>> +    IVSHMEM_DPRINTF("use msix, present: %d\n", msix_present(d));
>>>      if (!msix_present(d)) {
>>>          return;
>>>      }
>>
>> hmm do you want to say "ivshmem_use_msix(): present: true/false?"
>> Or do you want to say something more generic about MSI-X in this case?
>>
>> As is the comment you have:
>>
>> 1) if it is specific to this function behavior, it does not help to look up
>> the correct function
> 
> It's actually easy to locate with a grep "use msix" in ivshmem code (the 
> macro prepend IVHSMEM:)
> 
>> 2) if it is a more generic comment, it does not help to understand what is
>> going on
>>
>> Can you explain more what the purpose of that debug statement is?
> 
> It helps to trace what's going on, at least it helped me. But if it's 
> superflous, we can remove it (though it's really only there to help 
> developers)
> 

Ok lets be nice to them and say ivshmem_use_msix in there, so they find stuff 
quickly?

$ time fgrep -R "use msix" *
/.../
real 0m27.846s
user 0m0.923s
sys  0m0.667s

$ time gid ivshmem_use_msix
/.../
real 0m0.003s
user 0m0.000s
sys  0m0.000s