| Message ID | 20180813171132.21939-3-cota@braap.org |
|---|---|
| State | New |
| Headers | show |
| Series | synchronization profiler | expand |
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
* 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
"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.
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
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,
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 {
Signed-off-by: Emilio G. Cota <cota@braap.org> --- monitor.c | 7 +++++++ hmp-commands-info.hx | 16 ++++++++++++++++ 2 files changed, 23 insertions(+)