Do not enable QOM debugging by default

PATCH In review BALATON Zoltan 4 participants 10 messages Jul 16, 2018 – Jul 17, 2018

Share & tools

BALATON Zoltan

author

2018-07-16 19:58 UTC #0 lore raw

PATCH 1/1 Do not enable QOM debugging by default

Commit 3556c233d 5 years ago added an option to disable QOM debugging, noting that it can have high performance cost but left the default to on. Change the default to off and only enable it when debugging is requested to avoid the performance penalty for those compiling without debug options.

Signed-off-by BALATON Zoltan <[email protected]>

---
 configure | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

configure +2 -1

index 2a7796e..a8fc1ed 100755
@@ -415,7 +415,7 @@ bsd_user="no"
 blobs="yes"
 pkgversion=""
 pie=""
-qom_cast_debug="yes"
+qom_cast_debug="no"
 trace_backends="log"
 trace_file="trace"
 spice=""

@@ -1062,6 +1062,7 @@ for opt do
       debug_tcg="yes"
       debug_mutex="yes"
       debug="yes"
+      qom_cast_debug="yes"
       strip_opt="no"
       fortify_source="no"
   ;;

Signature · 1 line

2.7.6

Peter Maydell

2018-07-16 20:41 UTC #1 lore raw

Quoted 6 lines · BALATON Zoltan

Commit 3556c233d 5 years ago added an option to disable QOM debugging, noting that it can have high performance cost but left the default to on. Change the default to off and only enable it when debugging is requested to avoid the performance penalty for those compiling without debug options.
Signed-off-by BALATON Zoltan <[email protected]>

Looking at the code, doesn't this disable all the type checking on the QOM casts? That is not something I think we should drop, in the same way that we do not disable assert()s even in the non-debug build.

Is this coming up as significant in profiling? In the past we've done some special casing if there are particular QOM casts in hot paths that use significant runtime.

thanks
-- PMM

BALATON Zoltan

author

2018-07-16 21:08 UTC #2 lore raw

Quoted 8 lines · Peter Maydell

Quoted 6 lines · BALATON Zoltan
Commit 3556c233d 5 years ago added an option to disable QOM debugging, noting that it can have high performance cost but left the default to on. Change the default to off and only enable it when debugging is requested to avoid the performance penalty for those compiling without debug options.
Signed-off-by BALATON Zoltan <[email protected]>

Quoted 8 lines

Looking at the code, doesn't this disable all the type checking on the QOM casts? That is not something I think we should drop, in the same way that we do not disable assert()s even in the non-debug build.
Is this coming up as significant in profiling? In the past we've done some special casing if there are particular QOM casts in hot paths that use significant runtime.

My profiling results are not very accurate (could only gather sample based results with oprofile as --enable-gprof haven't worked for me) so I don't have numbers but I did see object_class_dynamic_cast_assert coming out among the top few without disabling this option but I don't know which call sites are responsible.

Are there any recommendations for profiling QEMU (especially TCG) somewhere that I should be aware of?

Regards,
BALATON Zoltan

Daniel P. Berrangé

2018-07-17 09:40 UTC #3 lore raw

In reply to Peter Maydell

Quoted 8 lines · Peter Maydell

Quoted 6 lines · BALATON Zoltan
Commit 3556c233d 5 years ago added an option to disable QOM debugging, noting that it can have high performance cost but left the default to on. Change the default to off and only enable it when debugging is requested to avoid the performance penalty for those compiling without debug options.
Signed-off-by BALATON Zoltan <[email protected]>

Quoted 8 lines

Looking at the code, doesn't this disable all the type checking on the QOM casts? That is not something I think we should drop, in the same way that we do not disable assert()s even in the non-debug build.
Is this coming up as significant in profiling? In the past we've done some special casing if there are particular QOM casts in hot paths that use significant runtime.

There might also be scope for doing optimization of the object_dynamic_cast_assert() implementation too.

Regards,
Daniel

Signature · 3 lines

|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

BALATON Zoltan

author

2018-07-17 15:09 UTC #4 lore raw

[Qemu-devel] Profiling results (was: Re: [PATCH] Do not enable QOM debugging by default)

In reply to Peter Maydell

Quoted 1 line · Peter Maydell

Is this coming up as significant in profiling? In the past we've

This seems to depend on the workload. From the cases I'm interested in AROS and AmigaOS on qemu-system-ppc -M sam460ex does not seem to be effected much (object_class_dynamic_cast_assert is not in top 10 with <2%) but for MorphOS on mac99 this seems to be significant. This is with default configure (--enable-qom-cast-debug):

%       cum. %     linenr info                 symbol name
9.7057   9.7057    exec-all.h:410              helper_lookup_tb_ptr
8.0330  17.7387    object.c:711                object_class_dynamic_cast_assert
6.9411  24.6798    cputlb.c:793                io_readx
6.3219  31.0017    sm501_template.h:62         draw_line16_32
5.3601  36.3617    cputlb.c:114                tlb_flush_nocheck
3.6170  39.9787    translate-all.c:749         page_trylock_add
3.1188  43.0975    translate-all.c:803         page_collection_lock
3.0405  46.1380    exec.c:3025                 iotlb_to_section
2.7044  48.8424    softmmu_template.h:112      helper_ret_ldub_mmu
2.4154  51.2578    memory.c:1350               memory_region_access_valid

and improves a bit (but not much) with --disable-qom-cast-debug

%        cum. %     linenr info                 symbol name
10.2063  10.2063    exec-all.h:410              helper_lookup_tb_ptr
 7.1581  17.3644    object.c:711                object_class_dynamic_cast_assert
 5.9297  23.2941    sm501_template.h:62         draw_line16_32
 5.9227  29.2168    cputlb.c:793                io_readx
 5.3030  34.5198    cputlb.c:114                tlb_flush_nocheck
 3.6445  38.1643    memory.c:1350               memory_region_access_valid
 3.5499  41.7142    softmmu_template.h:112      helper_ret_ldub_mmu
 3.0383  44.7525    translate-all.c:803         page_collection_lock
 2.9735  47.7260    memory.c:1415               memory_region_dispatch_read
 2.9503  50.6763    translate-all.c:749         page_trylock_add

But the workloads may not have been 100% identical so this is not conclusive, maybe this debug code is not that expensive at the moment.

AROS on sam460ex has a different profile:

%        cum. %     linenr info                 symbol name
8.9905   8.9905     translate-all.c:749         page_trylock_add
8.7658  17.7563     exec-all.h:410              helper_lookup_tb_ptr
7.7349  25.4911     translate-all.c:803         page_collection_lock
5.8246  31.3158     cputlb.c:924                victim_tlb_hit
3.1640  34.4797     cpus.c:347                  cpu_get_clock
3.1538  37.6335     translate-all.c:788         tb_page_addr_cmp
2.7969  40.4304     exec.c:435                  address_space_translate_internal
2.6647  43.0951     memory.c:571                access_with_adjusted_size
2.0615  45.1567     exec.c:569                  flatview_do_translate
1.9586  47.1153     memory.c:1350               memory_region_access_valid

Would anyone be able to guess what are the places that should be looked at or what to check to get more info on this?

Regards,
BALATON Zoltan

Mark Cave-Ayland

2018-07-17 17:10 UTC #5 lore raw

Re: [Qemu-devel] [Qemu-ppc] Profiling results

Quoted 49 lines · BALATON Zoltan

Quoted 1 line · Peter Maydell
Is this coming up as significant in profiling? In the past we've
This seems to depend on the workload. From the cases I'm interested in AROS and AmigaOS on qemu-system-ppc -M sam460ex does not seem to be effected much (object_class_dynamic_cast_assert is not in top 10 with <2%) but for MorphOS on mac99 this seems to be significant. This is with default configure (--enable-qom-cast-debug):
%       cum. %     linenr info                 symbol name 9.7057   9.7057    exec-all.h:410              helper_lookup_tb_ptr
8.0330 17.7387    object.c:711 object_class_dynamic_cast_assert
6.9411 24.6798    cputlb.c:793                io_readx 6.3219 31.0017    sm501_template.h:62         draw_line16_32 5.3601 36.3617    cputlb.c:114                tlb_flush_nocheck 3.6170 39.9787    translate-all.c:749         page_trylock_add 3.1188 43.0975    translate-all.c:803         page_collection_lock 3.0405 46.1380    exec.c:3025                 iotlb_to_section 2.7044 48.8424    softmmu_template.h:112      helper_ret_ldub_mmu 2.4154 51.2578    memory.c:1350               memory_region_access_valid
and improves a bit (but not much) with --disable-qom-cast-debug
%        cum. %     linenr info                 symbol name 10.2063 10.2063    exec-all.h:410              helper_lookup_tb_ptr
7.1581 17.3644    object.c:711
object_class_dynamic_cast_assert
5.9297 23.2941    sm501_template.h:62         draw_line16_32 5.9227 29.2168    cputlb.c:793                io_readx 5.3030 34.5198    cputlb.c:114                tlb_flush_nocheck 3.6445 38.1643    memory.c:1350               memory_region_access_valid 3.5499 41.7142    softmmu_template.h:112      helper_ret_ldub_mmu 3.0383 44.7525    translate-all.c:803         page_collection_lock 2.9735 47.7260    memory.c:1415
memory_region_dispatch_read
2.9503 50.6763    translate-all.c:749         page_trylock_add
But the workloads may not have been 100% identical so this is not conclusive, maybe this debug code is not that expensive at the moment.
AROS on sam460ex has a different profile:
%        cum. %     linenr info                 symbol name 8.9905   8.9905     translate-all.c:749         page_trylock_add 8.7658 17.7563     exec-all.h:410              helper_lookup_tb_ptr 7.7349 25.4911     translate-all.c:803         page_collection_lock 5.8246 31.3158     cputlb.c:924                victim_tlb_hit 3.1640 34.4797     cpus.c:347                  cpu_get_clock 3.1538 37.6335     translate-all.c:788         tb_page_addr_cmp
2.7969 40.4304     exec.c:435 address_space_translate_internal
2.6647 43.0951     memory.c:571                access_with_adjusted_size 2.0615 45.1567     exec.c:569                  flatview_do_translate 1.9586 47.1153     memory.c:1350               memory_region_access_valid

Quoted 1 line

Would anyone be able to guess what are the places that should be looked at or what to check to get more info on this?

My first thought is that there is a QOM cast somewhere in a hot path on -M mac99 - can you show us the call stack information from the profile?

I had a similar issue with SPARC32 whereby each DMA request needs to be manually word-swapped, so instead of adding the QOM cast into these routines I did a direct C cast from the opaque to ensure that the overhead was as little as possible.

ATB,

Mark.

BALATON Zoltan

author

2018-07-17 19:35 UTC #6 lore raw

Re: [Qemu-devel] [Qemu-ppc] Profiling results

Quoted 13 lines · Mark Cave-Ayland

Quoted 13 lines
MorphOS on mac99 this seems to be significant. This is with default configure (--enable-qom-cast-debug):
%?????? cum. %???? linenr info???????????????? symbol name 9.7057?? 9.7057??? exec-all.h:410????????????? helper_lookup_tb_ptr 8.0330? 17.7387??? object.c:711 object_class_dynamic_cast_assert 6.9411? 24.6798??? cputlb.c:793??????????????? io_readx 6.3219? 31.0017??? sm501_template.h:62???????? draw_line16_32 5.3601? 36.3617??? cputlb.c:114??????????????? tlb_flush_nocheck 3.6170? 39.9787??? translate-all.c:749???????? page_trylock_add 3.1188? 43.0975??? translate-all.c:803???????? page_collection_lock 3.0405? 46.1380??? exec.c:3025???????????????? iotlb_to_section 2.7044? 48.8424??? softmmu_template.h:112????? helper_ret_ldub_mmu 2.4154? 51.2578??? memory.c:1350?????????????? memory_region_access_valid

[...]

Quoted 1 line

My first thought is that there is a QOM cast somewhere in a hot path on -M mac99 - can you show us the call stack information from the profile?

Not really. Oprofile that gave me this profile could not display call graph for this call. I've tried again with the perf tool but I'm not quite sure how to interpret its results. If I'm not mistaken it points me in the direction of cpu_asidx_from_attrs, called from iotlb_to_section, called from io_readx. The object_class_dynamic_cast_assert call likely comes from OBJECT_CLASS_CHECK, expanded from OBJECT_GET_CLASS, expanded from CPU_GET_CLASS. Would that make any sense? Any idea what to do about it?

Thank you,
BALATON Zoltan

Mark Cave-Ayland

2018-07-17 19:57 UTC #7 lore raw

Re: [Qemu-devel] [Qemu-ppc] Profiling results

Quoted 14 lines · BALATON Zoltan

Quoted 13 lines · Mark Cave-Ayland
Quoted 13 lines
MorphOS on mac99 this seems to be significant. This is with default configure (--enable-qom-cast-debug):
%?????? cum. %???? linenr info???????????????? symbol name 9.7057?? 9.7057??? exec-all.h:410????????????? helper_lookup_tb_ptr 8.0330? 17.7387??? object.c:711 object_class_dynamic_cast_assert 6.9411? 24.6798??? cputlb.c:793??????????????? io_readx 6.3219? 31.0017??? sm501_template.h:62???????? draw_line16_32 5.3601? 36.3617??? cputlb.c:114??????????????? tlb_flush_nocheck 3.6170? 39.9787??? translate-all.c:749???????? page_trylock_add 3.1188? 43.0975??? translate-all.c:803???????? page_collection_lock 3.0405? 46.1380??? exec.c:3025???????????????? iotlb_to_section 2.7044? 48.8424??? softmmu_template.h:112????? helper_ret_ldub_mmu 2.4154? 51.2578??? memory.c:1350?????????????? memory_region_access_valid

Quoted 4 lines

[...]
Quoted 1 line
My first thought is that there is a QOM cast somewhere in a hot path on -M mac99 - can you show us the call stack information from the profile?
Not really. Oprofile that gave me this profile could not display call graph for this call. I've tried again with the perf tool but I'm not quite sure how to interpret its results. If I'm not mistaken it points me in the direction of cpu_asidx_from_attrs, called from iotlb_to_section, called from io_readx. The object_class_dynamic_cast_assert call likely comes from OBJECT_CLASS_CHECK, expanded from OBJECT_GET_CLASS, expanded from CPU_GET_CLASS. Would that make any sense? Any idea what to do about it?

Good question. A quick grep for 'asidx_from_attrs' shows that cc->asidx_from_attrs() isn't set for PPC targets, so as a quick test does replacing the inline function cpu_asidx_from_attrs() in include/qom/cpu.h with a simple "return 0" change the profile at all?

ATB,

Mark.

BALATON Zoltan

author

2018-07-17 20:46 UTC #8 lore raw

Re: [Qemu-devel] [Qemu-ppc] Profiling results

Quoted 15 lines · Mark Cave-Ayland

Quoted 14 lines · BALATON Zoltan
Quoted 13 lines · Mark Cave-Ayland
Quoted 13 lines
MorphOS on mac99 this seems to be significant. This is with default configure (--enable-qom-cast-debug):
%?????? cum. %???? linenr info???????????????? symbol name 9.7057?? 9.7057??? exec-all.h:410????????????? helper_lookup_tb_ptr 8.0330? 17.7387??? object.c:711 object_class_dynamic_cast_assert 6.9411? 24.6798??? cputlb.c:793??????????????? io_readx 6.3219? 31.0017??? sm501_template.h:62???????? draw_line16_32 5.3601? 36.3617??? cputlb.c:114??????????????? tlb_flush_nocheck 3.6170? 39.9787??? translate-all.c:749???????? page_trylock_add 3.1188? 43.0975??? translate-all.c:803???????? page_collection_lock 3.0405? 46.1380??? exec.c:3025???????????????? iotlb_to_section 2.7044? 48.8424??? softmmu_template.h:112????? helper_ret_ldub_mmu 2.4154? 51.2578??? memory.c:1350?????????????? memory_region_access_valid

Quoted 6 lines

Quoted 4 lines
[...]
Quoted 1 line
My first thought is that there is a QOM cast somewhere in a hot path on -M mac99 - can you show us the call stack information from the profile?
Not really. Oprofile that gave me this profile could not display call graph for this call. I've tried again with the perf tool but I'm not quite sure how to interpret its results. If I'm not mistaken it points me in the direction of cpu_asidx_from_attrs, called from iotlb_to_section, called from io_readx. The object_class_dynamic_cast_assert call likely comes from OBJECT_CLASS_CHECK, expanded from OBJECT_GET_CLASS, expanded from CPU_GET_CLASS. Would that make any sense? Any idea what to do about it?
Good question. A quick grep for 'asidx_from_attrs' shows that cc->asidx_from_attrs() isn't set for PPC targets, so as a quick test does replacing the inline function cpu_asidx_from_attrs() in include/qom/cpu.h with a simple "return 0" change the profile at all?

It does seem to lessen its impact but it's still higher than I expected:

%        cum. %     linenr info                 symbol name
10.7949  10.7949    exec-all.h:410              helper_lookup_tb_ptr
 7.8663  18.6612    cputlb.c:793                io_readx
 6.0265  24.6878    cputlb.c:114                tlb_flush_nocheck
 4.0671  28.7548    sm501_template.h:62         draw_line16_32
 4.0559  32.8107    object.c:765                object_class_dynamic_cast_assert
 3.3780  36.1887    memory.c:1350               memory_region_access_valid
 2.8920  39.0808    qemu-thread-posix.c:61      qemu_mutex_lock_impl
 2.7187  41.7995    memory.c:1415               memory_region_dispatch_read
 2.6011  44.4006    qht.c:487                   qht_lookup_custom
 2.5356  46.9362    softmmu_template.h:112      helper_ret_ldub_mmu

Maybe it's called from somewhere else too? I know draw_line16_32 but I wonder where could helper_lookup_tb_ptr and tlb flushes come from? Those seem to be significant. And io_readx in itself seems to be too high on the list too. I wonder if it may have something to do with the background task trying to read non-implemented i2c stuff frequently (as discussed in point 2. in http://zero.eik.bme.hu/~balaton/qemu/amiga/#morphos).

Regards,
BALATON Zoltan

Peter Maydell

2018-07-17 21:54 UTC #9 lore raw

Re: [Qemu-devel] [Qemu-ppc] Profiling results

Quoted 8 lines · BALATON Zoltan

Quoted 4 lines · Mark Cave-Ayland
Good question. A quick grep for 'asidx_from_attrs' shows that cc->asidx_from_attrs() isn't set for PPC targets, so as a quick test does replacing the inline function cpu_asidx_from_attrs() in include/qom/cpu.h with a simple "return 0" change the profile at all?
It does seem to lessen its impact but it's still higher than I expected:

It may be worth special-casing the CPU method lookups (or at least that one) if we can, then...

Quoted 13 lines

%        cum. %     linenr info                 symbol name
10.7949  10.7949    exec-all.h:410              helper_lookup_tb_ptr
 7.8663  18.6612    cputlb.c:793                io_readx
 6.0265  24.6878    cputlb.c:114                tlb_flush_nocheck
 4.0671  28.7548    sm501_template.h:62         draw_line16_32
 4.0559  32.8107    object.c:765
object_class_dynamic_cast_assert
 3.3780  36.1887    memory.c:1350               memory_region_access_valid
 2.8920  39.0808    qemu-thread-posix.c:61      qemu_mutex_lock_impl
 2.7187  41.7995    memory.c:1415               memory_region_dispatch_read
 2.6011  44.4006    qht.c:487                   qht_lookup_custom
 2.5356  46.9362    softmmu_template.h:112      helper_ret_ldub_mmu

Quoted 4 lines

Maybe it's called from somewhere else too? I know draw_line16_32 but I wonder where could helper_lookup_tb_ptr and tlb flushes come from? Those seem to be significant. And io_readx in itself seems to be too high on the list too.

helper_lookup_tb_ptr is part of TCG -- it's where we look for the next TB to go to. Any non-computed branch to a different page will result in our calling this. So it's high on the profile because we do it a lot, I think, but that's not necessarily a problem as such.

io_readx is the slow path for guest memory accesses -- any guest access to something that's not RAM will have to go through here. My first guess (given the other things in the profile, especially helper_ret_ldub_mmu, memory_region_dispatch_read and memory_region_access_valid) is that the guest is in a tight loop doing a read on a device register a lot of the time.

Quoted 3 lines

I wonder if it may have something to do with the background task trying to read non-implemented i2c stuff frequently (as discussed in point
2. in http://zero.eik.bme.hu/~balaton/qemu/amiga/#morphos).

Could be, or some similar thing. If you suspect the i2c you could try putting in an unimplemented-device stub in the right place and see how often -d unimp yells about reads to it.

So overall I'd be a little wary of optimizing based on this profile, because I suspect it's atypical -- the guest is sat in a tight polling loop and the profile says "all the functions in the code path for doing device access are really hot". The fix is to improve our model so the guest doesn't get stuck like that, not to try to slightly improve the speed of device accesses (we call it the "slow path" for a reason :-))

(But places like asidx_from_attrs are likely to be on hot paths in general, so having the QOM class lookup there be overly heavyweight is maybe worth fixing anyhow.)

thanks
-- PMM