[Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'

Emilio G. Cota posted 3 patches 7 years, 2 months ago
There is a newer version of this series
[Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Emilio G. Cota 7 years, 2 months ago
Signed-off-by: Emilio G. Cota <cota@braap.org>
---
 monitor.c            |  7 +++++++
 hmp-commands-info.hx | 16 ++++++++++++++++
 2 files changed, 23 insertions(+)

diff --git a/monitor.c b/monitor.c
index 77861e96af..66d8d85b97 100644
--- a/monitor.c
+++ b/monitor.c
@@ -1454,6 +1454,13 @@ static void hmp_info_opcount(Monitor *mon, const QDict *qdict)
 }
 #endif
 
+static void hmp_info_sync(Monitor *mon, const QDict *qdict)
+{
+    int64_t max = qdict_get_try_int(qdict, "max", 10);
+
+    qsp_report((FILE *)mon, monitor_fprintf, max);
+}
+
 static void hmp_info_history(Monitor *mon, const QDict *qdict)
 {
     int i;
diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
index 70639f656a..56a3249bad 100644
--- a/hmp-commands-info.hx
+++ b/hmp-commands-info.hx
@@ -297,6 +297,22 @@ STEXI
 @item info opcount
 @findex info opcount
 Show dynamic compiler opcode counters
+ETEXI
+
+    {
+        .name       = "sync",
+        .args_type  = "max:i?",
+        .params     = "[max]",
+        .help       = "show sync profiling info for "
+	              "up to max entries (default: 10). "
+		      "Entries are sorted by wait time.",
+        .cmd        = hmp_info_sync,
+    },
+
+STEXI
+@item info sync
+@findex sync
+Show sync profiling info.
 ETEXI
 
     {
-- 
2.17.1


Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Paolo Bonzini 7 years, 2 months ago
On 13/08/2018 19:11, Emilio G. Cota wrote:
> diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
> index 70639f656a..56a3249bad 100644
> --- a/hmp-commands-info.hx
> +++ b/hmp-commands-info.hx
> @@ -297,6 +297,22 @@ STEXI
>  @item info opcount
>  @findex info opcount
>  Show dynamic compiler opcode counters
> +ETEXI
> +
> +    {
> +        .name       = "sync",
> +        .args_type  = "max:i?",
> +        .params     = "[max]",
> +        .help       = "show sync profiling info for "
> +	              "up to max entries (default: 10). "
> +		      "Entries are sorted by wait time.",
> +        .cmd        = hmp_info_sync,
> +    },
> +
> +STEXI

Would it make sense to add a flag to sort by average wait time, and one
to coalesce all mutexes for the same call site?

Can be done separately of course.

Paolo

Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Emilio G. Cota 7 years, 2 months ago
On Tue, Aug 14, 2018 at 10:14:01 +0200, Paolo Bonzini wrote:
> On 13/08/2018 19:11, Emilio G. Cota wrote:
> Would it make sense to add a flag to sort by average wait time

Done:

(qemu) help info sync-profile
info sync-profile [-m] [max] -- show sync profiling info \
for up to max entries (default: 10). By default, entries \
are sorted by total wait time; -m sorts by mean wait time.

(qemu) info sync-profile 3 
Type               Object  Call site       Wait Time (s)         Count  Average (us)
------------------------------------------------------------------------------------
condvar    0x560cc9909e50  cpus.c:1165          63.63428         16081       3957.11
condvar    0x560cc9909e50  cpus.c:1415           0.21074             2     105371.07
BQL mutex  0x560cc85a3fa0  util/rcu.c:269        0.20227            20      10113.60
------------------------------------------------------------------------------------

(qemu) info sync-profile -m 3
Type               Object  Call site       Wait Time (s)         Count  Average (us)
------------------------------------------------------------------------------------
condvar    0x560cc9909e50  cpus.c:1415           0.21074             2     105371.07
BQL mutex  0x560cc85a3fa0  util/rcu.c:269        0.20227            21       9632.00
condvar    0x560cc9909e50  cpus.c:1165          71.92799         18167       3959.27
------------------------------------------------------------------------------------

>, and one to coalesce all mutexes for the same call site?

I am not sure I understand. Do you mean to pass a specific call site,
so that we coalesce all entries related to the call site's object?
Or to keep the call sites separate, but only report entries related
to that specific call site's object?

Thanks,

		Emilio

Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Peter Xu 7 years, 2 months ago
On Tue, Aug 14, 2018 at 09:26:09PM -0400, Emilio G. Cota wrote:
> On Tue, Aug 14, 2018 at 10:14:01 +0200, Paolo Bonzini wrote:
> > On 13/08/2018 19:11, Emilio G. Cota wrote:
> > Would it make sense to add a flag to sort by average wait time
> 
> Done:
> 
> (qemu) help info sync-profile
> info sync-profile [-m] [max] -- show sync profiling info \
> for up to max entries (default: 10). By default, entries \
> are sorted by total wait time; -m sorts by mean wait time.
> 
> (qemu) info sync-profile 3 
> Type               Object  Call site       Wait Time (s)         Count  Average (us)
> ------------------------------------------------------------------------------------
> condvar    0x560cc9909e50  cpus.c:1165          63.63428         16081       3957.11
> condvar    0x560cc9909e50  cpus.c:1415           0.21074             2     105371.07
> BQL mutex  0x560cc85a3fa0  util/rcu.c:269        0.20227            20      10113.60
> ------------------------------------------------------------------------------------
> 
> (qemu) info sync-profile -m 3
> Type               Object  Call site       Wait Time (s)         Count  Average (us)
> ------------------------------------------------------------------------------------
> condvar    0x560cc9909e50  cpus.c:1415           0.21074             2     105371.07
> BQL mutex  0x560cc85a3fa0  util/rcu.c:269        0.20227            21       9632.00
> condvar    0x560cc9909e50  cpus.c:1165          71.92799         18167       3959.27
> ------------------------------------------------------------------------------------
> 
> >, and one to coalesce all mutexes for the same call site?
> 
> I am not sure I understand. Do you mean to pass a specific call site,
> so that we coalesce all entries related to the call site's object?
> Or to keep the call sites separate, but only report entries related
> to that specific call site's object?

I would guess Paolo means that whether we can merge entries that have
the same call site but with different object addresses.  I copied one
example from the commit message of your patch 1:

Type               Object  Call site          Wait Time (s)         Count  Average (us)
---------------------------------------------------------------------------------------
condvar    0x557ee3090e80  cpus.c:1084              1.69207          2916        580.27
condvar    0x557ee30ceb10  cpus.c:1084              1.43442          2404        596.68
...

IMHO merging of these two entries might be helpful when e.g. the
condvar used there is dynamically created/destroyed, then in this case
the object pointer might not that helpful, instead the statistics of
all the entries for the same call site might tell more.

Regards,

-- 
Peter Xu

Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Dr. David Alan Gilbert 7 years, 2 months ago
* Emilio G. Cota (cota@braap.org) wrote:
> Signed-off-by: Emilio G. Cota <cota@braap.org>
> ---
>  monitor.c            |  7 +++++++
>  hmp-commands-info.hx | 16 ++++++++++++++++
>  2 files changed, 23 insertions(+)
> 
> diff --git a/monitor.c b/monitor.c
> index 77861e96af..66d8d85b97 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -1454,6 +1454,13 @@ static void hmp_info_opcount(Monitor *mon, const QDict *qdict)
>  }
>  #endif
>  
> +static void hmp_info_sync(Monitor *mon, const QDict *qdict)
> +{
> +    int64_t max = qdict_get_try_int(qdict, "max", 10);
> +
> +    qsp_report((FILE *)mon, monitor_fprintf, max);
> +}
> +
>  static void hmp_info_history(Monitor *mon, const QDict *qdict)
>  {
>      int i;
> diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
> index 70639f656a..56a3249bad 100644
> --- a/hmp-commands-info.hx
> +++ b/hmp-commands-info.hx
> @@ -297,6 +297,22 @@ STEXI
>  @item info opcount
>  @findex info opcount
>  Show dynamic compiler opcode counters
> +ETEXI
> +
> +    {
> +        .name       = "sync",
> +        .args_type  = "max:i?",
> +        .params     = "[max]",
> +        .help       = "show sync profiling info for "
> +	              "up to max entries (default: 10). "
> +		      "Entries are sorted by wait time.",
> +        .cmd        = hmp_info_sync,
> +    },
> +
> +STEXI
> +@item info sync
> +@findex sync
> +Show sync profiling info.
>  ETEXI
>  
>      {

As long as this is just for devs I'm OK with this from the HMP side;
however, if you want to automate the display or wire it to other
tools then you should probably wire it up via QMP.

Dave

> -- 
> 2.17.1
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Markus Armbruster 7 years, 2 months ago
"Emilio G. Cota" <cota@braap.org> writes:

> Signed-off-by: Emilio G. Cota <cota@braap.org>
> ---
>  monitor.c            |  7 +++++++
>  hmp-commands-info.hx | 16 ++++++++++++++++
>  2 files changed, 23 insertions(+)
>
> diff --git a/monitor.c b/monitor.c
> index 77861e96af..66d8d85b97 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -1454,6 +1454,13 @@ static void hmp_info_opcount(Monitor *mon, const QDict *qdict)
>  }
>  #endif
>  
> +static void hmp_info_sync(Monitor *mon, const QDict *qdict)
> +{
> +    int64_t max = qdict_get_try_int(qdict, "max", 10);
> +
> +    qsp_report((FILE *)mon, monitor_fprintf, max);
> +}
> +
>  static void hmp_info_history(Monitor *mon, const QDict *qdict)
>  {
>      int i;
> diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
> index 70639f656a..56a3249bad 100644
> --- a/hmp-commands-info.hx
> +++ b/hmp-commands-info.hx
> @@ -297,6 +297,22 @@ STEXI
>  @item info opcount
>  @findex info opcount
>  Show dynamic compiler opcode counters
> +ETEXI
> +
> +    {
> +        .name       = "sync",

I think "info sync-profile" would be clearer.

> +        .args_type  = "max:i?",
> +        .params     = "[max]",
> +        .help       = "show sync profiling info for "
> +	              "up to max entries (default: 10). "
> +		      "Entries are sorted by wait time.",
> +        .cmd        = hmp_info_sync,
> +    },
> +
> +STEXI
> +@item info sync
> +@findex sync
> +Show sync profiling info.
>  ETEXI
>  
>      {

Please explain briefly why you think this command is not going to be
useful in QMP.  Recommend to do that right in your commit message.  For
instance, you could argue that the information provided is useful only
to developers, and developers are just fine with getting it from HMP
"info sync".

However, if we expect developers to further process the data, providing
it as JSON (via QMP) makes sense, because is saves them the trouble of
parsing your (undocumented) HMP output format.

If we decide we want to provide the functionality in QMP, I can help you
with the necessary code changes.

Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync'
Posted by Emilio G. Cota 7 years, 2 months ago
On Tue, Aug 14, 2018 at 10:43:47 +0100, Dr. David Alan Gilbert wrote:
> * Emilio G. Cota (cota@braap.org) wrote:
> > +@item info sync
> 
> As long as this is just for devs I'm OK with this from the HMP side;
> however, if you want to automate the display or wire it to other
> tools then you should probably wire it up via QMP.

On Tue, Aug 14, 2018 at 18:03:32 +0200, Markus Armbruster wrote:
> "Emilio G. Cota" <cota@braap.org> writes:
> > +@item info sync
> 
> Please explain briefly why you think this command is not going to be
> useful in QMP.  Recommend to do that right in your commit message.  For
> instance, you could argue that the information provided is useful only
> to developers, and developers are just fine with getting it from HMP
> "info sync".
> 
> However, if we expect developers to further process the data, providing
> it as JSON (via QMP) makes sense, because is saves them the trouble of
> parsing your (undocumented) HMP output format.
> 
> If we decide we want to provide the functionality in QMP, I can help you
> with the necessary code changes.

Thanks Dave and Markus for taking a look.

This is just for developers. This means (1) the info displayed and the
output format could change in the future, and (2) it is only meant
to be used from HMP "info sync-profile".

I'll include the above in the commit log, as Markus suggested.

> > +        .name       = "sync",
> 
> I think "info sync-profile" would be clearer.

Done.

Thanks,

		Emilio