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

[BALATON Zoltan]

On Tue, 17 Jul 2018, Mark Cave-Ayland wrote:
> On 17/07/18 20:35, BALATON Zoltan wrote:
> > On Tue, 17 Jul 2018, Mark Cave-Ayland wrote:
> > > > 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
> > [...]
> > > 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