search

mesonbuild / meson

The Meson Build System
http://mesonbuild.com
Apache License 2.0
5.52k stars 1.61k forks source link

`meson setup` takes 2.5 minutes for shared build (static takes 3 seconds) #11322

Open dotnwat opened 1 year ago

dotnwat commented 1 year ago

Describe the bug

meson setup takes 2.5 minutes for a shared library build, compared to 3 seconds for a static library build.

This is meson setup step for a shared library build of a project taking nearly 2.5 minutes to complete.

CC="ccache clang" CXX="ccache clang++" CC_LD=lld CXX_LD=lld time strace -tt --string-limit=100 meson setup builddir --default-library shared 2>&1 | tee strace-shared.log
138.27user 1.77system 2:20.29elapsed 99%CPU (0avgtext+0avgdata 1280588maxresident)k
96inputs+28544outputs (30major+773158minor)pagefaults 0swaps

The same exact setup with static library configuration takes 3 seconds.

CC="ccache clang" CXX="ccache clang++" CC_LD=lld CXX_LD=lld time strace -tt --string-limit=100 meson setup builddir --default-library static 2>&1 | tee strace-static.log
<clipped>
2.25user 1.32system 0:03.59elapsed 99%CPU (0avgtext+0avgdata 88496maxresident)k
120inputs+25704outputs (58major+456678minor)pagefaults 0swaps

Looking at the strace output it seems that over 1 minute is spent repeating this:

08:45:41.412750 write(3, "detecting CPU family based on trial='x86_64'\n", 45) = 45
08:45:41.412822 write(3, "detecting CPU family based on trial='x86_64'\n", 45) = 45
<clipped>
08:46:48.017806 write(3, "detecting CPU family based on trial='x86_64'\n", 45) = 45

Then there is a second phase of this same pattern later in the trace. Together that accounts for over 2 minutes.

To Reproduce

Upon request. This is potentially difficult for our private build, but also perhaps unnecessary if this is as simple as perhaps adding in a new CPU family?

Expected behavior

Fast setup step.

system parameters

processor       : 10                                                                                                                                                                                                                                                                                                                                                                          
vendor_id       : AuthenticAMD                                                                                                                                                                                                                                                                                                                                                                
cpu family      : 25                                                                                                                                                                                                                                                                                                                                                                          
model           : 97                                                                                                                                                                                                                                                                                                                                                                          
model name      : AMD Ryzen 9 7900X 12-Core Processor                                                                                                                                                                                                                                                                                                                                         
stepping        : 2                                                                                                                                                                                                                                                                                                                                                                           
microcode       : 0xa601203                                                                                                                                                                                                                                                                                                                                                                   
cpu MHz         : 3000.000                                                                                                                                                                                                                                                                                                                                                                    
cache size      : 1024 KB                                                                                                                                                                                                                                                                                                                                                                     
physical id     : 0                                                                                                                                                                                                                                                                                                                                                                           
siblings        : 24                                                                                                                                                                                                                                                                                                                                                                          
core id         : 12                                                                                                                                                                                                                                                                                                                                                                          
cpu cores       : 12                                                                                                                                                                                                                                                                                                                                                                          
apicid          : 24                                                                                                                                                                                                                                                                                                                                                                          
initial apicid  : 24                                                                                                                                                                                                                                                                                                                                                                          
fpu             : yes                                                                                                                                                                                                                                                                                                                                                                         
fpu_exception   : yes                                                                                                                                                                                                                                                                                                                                                                         
cpuid level     : 16                                                                                                                                                                                                                                                                                                                                                                          wp              : yes                                                                                                                                                                                                                                                                                                                                                                         flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good amd_lbr_v2 nopl nonstop_tsc cpuid extd_apicid aperfmperf rapl pni pclmulqdq monitor ssse3 fma cx16 sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt tce topoext perfctr_core perfctr_nb bpext perfctr_llc mwaitx cpb cat_l3 cdp_l3 hw_pstate ssbd mba perfmon_v2 ibrs ibpb stibp vmmcall fsgsbase bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm
_occup_llc cqm_mbm_total cqm_mbm_local avx512_bf16 clzero irperf xsaveerptr rdpru wbnoinvd cppc arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold avic v_vmsave_vmload vgif x2avic v_spec_ctrl avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq rdpid overflow_recov succor smca f
srm flush_l1d                                                                                                                                                                                                                                                                                                                                                                                 
bugs            : sysret_ss_attrs spectre_v1 spectre_v2 spec_store_bypass                                                                                                                                                                                                                                                                                                                     
bogomips        : 9382.11                                                                                                                                                                                                                                                                                                                                                                     
TLB size        : 3584 4K pages                                                                                                                                                                                                                                                                                                                                                               
clflush size    : 64                                                                                                                                                                                                                                                                                                                                                                          
cache_alignment : 64                                                                                                                                                                                                                                                                                                                                                                          
address sizes   : 48 bits physical, 48 bits virtual                                                                                                                                                                                                                                                                                                                                           
power management: ts ttp tm hwpstate cpb eff_freq_ro [13] [14]
eli-schwartz commented 1 year ago

That debug print should probably not be there TBH.

dotnwat commented 1 year ago

@eli-schwartz fwiw I commented out that line from your referenced PR and the meson setup step still takes 2.5 minutes.

strace shows that meson is sitting in some sort of loop

09:56:24.894164 mmap(NULL, 10166272, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f09533fc000
09:56:24.897452 mremap(0x7f09533fc000, 10166272, 11767808, MREMAP_MAYMOVE) = 0x7f094998a000
09:56:24.897979 mremap(0x7f094998a000, 11767808, 13254656, MREMAP_MAYMOVE) = 0x7f095310a000
09:56:24.898743 mremap(0x7f095310a000, 13254656, 17043456, MREMAP_MAYMOVE) = 0x7f0949482000
09:56:24.899990 mremap(0x7f0949482000, 17043456, 20103168, MREMAP_MAYMOVE) = 0x7f0928ede000
09:56:25.974846 mmap(NULL, 10166272, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f09533fc000
09:56:25.978206 mremap(0x7f09533fc000, 10166272, 11767808, MREMAP_MAYMOVE) = 0x7f094998a000
09:56:25.978759 mremap(0x7f094998a000, 11767808, 13254656, MREMAP_MAYMOVE) = 0x7f095310a000
09:56:25.979525 mremap(0x7f095310a000, 13254656, 17043456, MREMAP_MAYMOVE) = 0x7f0949482000
09:56:25.980778 mremap(0x7f0949482000, 17043456, 20103168, MREMAP_MAYMOVE) = 0x7f0927bb2000
09:56:27.231332 mmap(NULL, 10166272, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f09533fc000
09:56:27.234899 mremap(0x7f09533fc000, 10166272, 11767808, MREMAP_MAYMOVE) = 0x7f094998a000
09:56:27.235446 mremap(0x7f094998a000, 11767808, 13254656, MREMAP_MAYMOVE) = 0x7f095310a000
09:56:27.236224 mremap(0x7f095310a000, 13254656, 17043456, MREMAP_MAYMOVE) = 0x7f0949482000
09:56:27.237504 mremap(0x7f0949482000, 17043456, 20103168, MREMAP_MAYMOVE) = 0x7f0926886000
09:56:28.334355 brk(0x55b9da934000)     = 0x55b9da934000

which looks like something is just sitting in a loop malloc/freeing.

is there a way to get a trace at the python/meson level of whats going on?

eli-schwartz commented 1 year ago

meson setup --profile-self.

On the other hand, if we're spending significant enough time repeating this file write that you'd think it's the cause of the slowdown, we shouldn't be logging it that many times anyway as it clutters the log. :P

dotnwat commented 1 year ago

On the other hand, if we're spending significant enough time repeating this file write that you'd think it's the cause of the slowdown, we shouldn't be logging it that many times anyway as it clutters the log. :P

I agree it shouldn't be logged, but writing like this doesn't account for 2 minutes of time. I think it is merely pointing at the area of Meson that is eating up the time. For example, I'm waiting on meson setup --profile-self to finish (with the log line commented out), and I've been waiting over 5 minutes. Meson is running at 100% CPU utilization.

dotnwat commented 1 year ago

The --profile-self run finished. I ran it under time and we can see it ended up taking nearly 10 minutes to exit.

[2.525]   Subprojects
[2.525]     avro           : [2.525] YES
[2.525]     base64         : [2.525] YES
[2.525]     crc32c         : [2.525] YES
[2.525]     ctre           : [2.525] YES
[2.525]     fmt            : [2.525] YES
[2.525]     hdr_histogram  : [2.525] YES
[2.525]     rapidjson      : [2.525] YES
[2.525]     roaring        : [2.525] YES
[2.525]     seastar        : [2.525] YES
[2.525] 
[2.525]   User defined options
[2.525]     default_library: [2.525]
                     shared
[2.525] 
[2.550] Found ninja-1.10.2 at /usr/bin/ninja

532.04user 1.13system 8:53.82elapsed 99%CPU (0avgtext+0avgdata 1281728maxresident)k
40inputs+29128outputs (38major+770934minor)pagefaults 0swaps
eli-schwartz commented 1 year ago

There should now be a file in the build directory called meson-private/profile-introspector.log.

dotnwat commented 1 year ago

Ok got it. How to decode?

dotnwat commented 1 year ago

ok i think this is what you are looking for?

 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      130    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copyreg.py:113(_slotnames)
     2080    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/platform.py:823(uname)
      127    0.000    0.000    0.001    0.000 /usr/lib64/python3.11/pathlib.py:56(parse_parts)
      127    0.000    0.000    0.001    0.000 /usr/lib64/python3.11/pathlib.py:484(_parse_args)
  260/130    0.001    0.000    0.004    0.000 /usr/lib64/python3.11/copy.py:259(_reconstruct)
 1047/130    0.002    0.000    0.005    0.000 /usr/lib64/python3.11/copy.py:128(deepcopy)
    41935    0.003    0.000    0.025    0.000 /usr/lib64/python3.11/json/encoder.py:414(_iterencode)
      308    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2095(_classify_argument)
        9    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/json/encoder.py:205(iterencode)
75351/41911    0.009    0.000    0.021    0.000 /usr/lib64/python3.11/json/encoder.py:278(_iterencode_list)
59434/41796    0.008    0.000    0.017    0.000 /usr/lib64/python3.11/json/encoder.py:334(_iterencode_dict)
        2    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:359(get_test_list)
        1    0.000    0.000  266.491  266.491 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:59(get_meson_introspection_types)
        1    0.000    0.000    0.034    0.034 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:506(write_intro_info)
      308    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2132(__init__)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:107(list_installed)
        1    0.001    0.001    0.005    0.005 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:214(list_targets)
      306    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/coredata.py:616(get_option)
      260    0.001    0.000    0.003    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:279(detect_cpu_family)
       18    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/dependencies/base.py:133(get_compile_args)
        7    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:286(add_keys)
        1    0.000    0.000    0.002    0.002 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:264(list_buildoptions)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:126(list_install_plan)
      130    0.000    0.000    0.000    0.000 <string>:2(__init__)
      130    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:283(get_target_filename)
        2   91.762   45.881  266.491  133.245 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1087(create_test_serialisation)
      110    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1796(get_introspection_data)
        1    0.000    0.000  266.533  266.533 <string>:1(<module>)
      306    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/ninjabackend.py:3461(get_introspection_data)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:95(__str__)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:218(__post_init__)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/interpreter/interpreterobjects.py:671(get_exe)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/interpreter/interpreterobjects.py:674(get_name)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1089(<lambda>)
      110    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1821(<listcomp>)
        3    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1820(<listcomp>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:386(list_benchmarks)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:313(<lambda>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:383(list_tests)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/interpreter/interpreter.py:524(get_build_def_files)
      130    0.000    0.000    0.002    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1161(<listcomp>)
      306    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:247(<listcomp>)
        1    0.000    0.000    0.001    0.001 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:330(list_buildsystem_files)
      306    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:244(<listcomp>)
        1    0.000    0.000    0.001    0.001 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:333(<listcomp>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:313(<dictcomp>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:317(<dictcomp>)
       18    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/dependencies/base.py:157(get_link_args)
       18    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/dependencies/base.py:167(found)
       18    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/dependencies/base.py:178(get_version)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:389(list_projinfo)
      131    0.000    0.000    0.000    0.000 {method 'update' of '_hashlib.HASH' objects}
      131    0.000    0.000    0.000    0.000 {method 'hexdigest' of '_hashlib.HASH' objects}
      131    0.000    0.000    0.000    0.000 {built-in method _hashlib.openssl_sha256}
      131    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:599(construct_id_from_path)
      196    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:1273(should_install)
      110    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:2492(should_install)
      113    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:2501(get_outputs)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:740(get_coredata)
        2    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:778(get_source_dir)
150316869    8.414    0.000    8.414    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:781(get_build_dir)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:349(list_deps)
       19    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/coredata.py:376(values)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/coredata.py:787(is_cross_build)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/coredata.py:743(is_per_machine_option)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/envconfig.py:253(get)
        1    0.000    0.000  266.533  266.533 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:516(generate_introspection_file)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/envconfig.py:287(is_windows)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/envconfig.py:293(is_cygwin)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/envconfig.py:305(is_darwin)
    21537    0.002    0.000    0.002    0.000 {built-in method _json.encode_basestring_ascii}
       11    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:51(__init__)
      260    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:387(detect_system)
      108    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:435(relative_name)
      708    0.001    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:480(__getitem__)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:621(is_openbsd)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:625(is_windows)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:644(is_netbsd)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:648(is_freebsd)
        9    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/json/encoder.py:260(_make_iterencode)
      216    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:432(__hash__)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:74(<lambda>)
       58    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:476(__init__)
        1    0.000    0.000    0.002    0.002 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:75(<lambda>)
      131    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:1035(has_path_sep)
        1    0.000    0.000    0.001    0.001 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:76(<lambda>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:77(<lambda>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:79(<lambda>)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2272(is_backend)
      142    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2276(is_builtin)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2280(is_compiler)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2284(is_project)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2288(is_base)
       58    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:468(get_lower_case_name)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:1756(__len__)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:1875(type_suffix)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:2568(type_suffix)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:657(is_qnx)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:660(is_aix)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:1753(__iter__)
     2906    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2178(_to_tuple)
      306    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:156(get_target_dir)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:128(<dictcomp>)
      260    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:269(any_compiler_has_define)
      260    0.000    0.000    0.004    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:848(need_exe_wrapper)
      792    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2175(__hash__)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:310(get_targets)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:313(get_tests)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:316(get_benchmarks)
      306    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:580(get_basename)
150316741    7.923    0.000    7.923    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:583(get_subdir)
      306    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:586(get_typename)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:1240(get_filename)
      196    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:1243(get_outputs)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:310(<dictcomp>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:311(<dictcomp>)
      130    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:854(get_exe_wrapper)
      131    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:618(get_id)
      131    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:589(_get_id_hash)
      260    0.000    0.000    0.003    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:411(machine_info_can_run)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:80(<lambda>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:81(<lambda>)
        1    0.000    0.000    0.005    0.005 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:82(<lambda>)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/mintro.py:83(<lambda>)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:1007(get_all_link_deps)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:731(is_cross_build)
       18    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/coredata.py:321(values)
      108    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:405(absolute_path)
      157    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2191(__str__)
      887    0.000    0.000    0.001    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2181(__eq__)
      566    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/universal.py:2186(__lt__)
  261/260    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copy.py:201(_deepcopy_list)
      395    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copy.py:182(_deepcopy_atomic)
      129    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/core.py:117(prepend)
      130    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/core.py:135(get_env)
      130    0.000    0.000    0.003    0.000 /usr/lib64/python3.11/copy.py:227(_deepcopy_dict)
      129    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/core.py:130(_prepend)
        1    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copy.py:211(<listcomp>)
      520    0.000    0.000    0.001    0.000 /usr/lib64/python3.11/copy.py:264(<genexpr>)
        1    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copy.py:210(_deepcopy_tuple)
      652    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copy.py:243(_keep_alive)
        9    0.006    0.001    0.033    0.004 /usr/lib64/python3.11/json/__init__.py:120(dump)
      127    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/pathlib.py:549(as_posix)
        1    0.000    0.000    0.000    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/utils/core.py:121(_set)
      130    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/copyreg.py:104(__newobj__)
     1820    0.000    0.000    0.001    0.000 /usr/lib64/python3.11/platform.py:912(system)
      260    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/platform.py:949(machine)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      254    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/pathlib.py:239(splitroot)
      127    0.000    0.000    0.001    0.000 /usr/lib64/python3.11/pathlib.py:469(__new__)
      127    0.000    0.000    0.001    0.000 /usr/lib64/python3.11/pathlib.py:504(_from_parts)
      127    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/pathlib.py:523(_format_parsed_parts)
      127    0.000    0.000    0.000    0.000 /usr/lib64/python3.11/pathlib.py:536(__str__)
     2263    0.000    0.000    0.000    0.000 {built-in method _abc._abc_instancecheck}
    22/18    0.000    0.000    0.000    0.000 {built-in method _abc._abc_subclasscheck}
    41926    0.002    0.000    0.002    0.000 {method 'write' of '_io.TextIOWrapper' objects}
        9    0.000    0.000    0.000    0.000 {method 'flush' of '_io.TextIOWrapper' objects}
        9    0.000    0.000    0.000    0.000 {method '__exit__' of '_io._IOBase' objects}
        9    0.000    0.000    0.000    0.000 {built-in method io.open}
        9    0.000    0.000    0.000    0.000 {built-in method posix.replace}
      417    0.000    0.000    0.000    0.000 {built-in method posix._path_normpath}
150318588    4.965    0.000    4.965    0.000 {built-in method posix.fspath}
     1131    0.000    0.000    0.000    0.000 {built-in method sys.intern}
        1    0.000    0.000  266.533  266.533 {built-in method builtins.exec}
      520    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
      260    0.000    0.000    0.000    0.000 {built-in method builtins.hasattr}
      308    0.000    0.000    0.000    0.000 {built-in method builtins.hash}
     5449    0.000    0.000    0.000    0.000 {built-in method builtins.id}
300680304   11.216    0.000   11.217    0.000 {built-in method builtins.isinstance}
      390    0.000    0.000    0.000    0.000 {built-in method builtins.issubclass}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.iter}
      581    0.000    0.000    0.000    0.000 {built-in method builtins.len}
       10    0.000    0.000    0.001    0.000 {built-in method builtins.sorted}
      131    0.000    0.000    0.000    0.000 {method 'encode' of 'str' objects}
      389    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
      252    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
      257    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
     2080    0.000    0.000    0.000    0.000 {method 'lower' of 'str' objects}
      127    0.000    0.000    0.000    0.000 {method 'lstrip' of 'str' objects}
150320730    9.521    0.000    9.521    0.000 {method 'startswith' of 'str' objects}
150318602    9.390    0.000    9.390    0.000 {method 'endswith' of 'str' objects}
      260    0.000    0.000    0.001    0.000 {method '__reduce_ex__' of 'object' objects}
      257    0.000    0.000    0.000    0.000 {built-in method __new__ of type object at 0x7f42c9cee700}
        1    0.000    0.000    0.000    0.000 {method 'keys' of 'collections.OrderedDict' objects}
        1    0.000    0.000    0.000    0.000 {method 'values' of 'collections.OrderedDict' objects}
        2    0.000    0.000    0.000    0.000 {method 'items' of 'collections.OrderedDict' objects}
      417    0.000    0.000    0.000    0.000 <frozen posixpath>:389(normpath)
150317917   96.161    0.000  144.483    0.000 <frozen posixpath>:71(join)
150317917   17.864    0.000   24.447    0.000 <frozen posixpath>:41(_get_sep)
        9    0.000    0.000    0.000    0.000 <frozen codecs>:186(__init__)
    22/18    0.000    0.000    0.000    0.000 <frozen abc>:121(__subclasscheck__)
     2263    0.000    0.000    0.001    0.000 <frozen abc>:117(__instancecheck__)
150316997    9.266    0.000    9.266    0.000 {method 'add' of 'set' objects}
     2752    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
     1201    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
      474    0.000    0.000    0.000    0.000 {method 'values' of 'dict' objects}
      130    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}
      130    0.000    0.000    0.000    0.000 {method 'copy' of 'dict' objects}
     2936    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
      127    0.000    0.000    0.000    0.000 {method 'reverse' of 'list' objects}
      130    0.000    0.000    0.000    0.000 {method 'get' of 'mappingproxy' objects}
dotnwat commented 1 year ago

@dcbaker i don't think that #11323 should close this issue. can we reopen it?

eli-schwartz commented 1 year ago

Sorry, I had intended to update that PR to not mark this as closed, but got distracted by another bug report instead. :D

dcbaker commented 1 year ago

That’s a lot of time in path.join

we’re doing something really dumb here, not sure what yet though

dotnwat commented 1 year ago

I think this might be helpful. Ran with python3 -m trace --trace -g $(which meson) setup .... And see this repeated thousands of times

 --- modulename: posixpath, funcname: join                                                 
89.55 <frozen posixpath>(76): 89.55 <frozen posixpath>(77):  --- modulename: posixpath, funcname: _get_sep                              
89.55 <frozen posixpath>(42): 89.55 <frozen posixpath>(45): 89.55 <frozen posixpath>(78): 89.55 <frozen posixpath>(79): 89.55 <frozen posixpath>(80): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(83): 89.55 <frozen posixpath>(85): 89.55 <frozen posixpath>(88): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(92): 89.55 backends.py(1148):                         for
 l in d.get_all_link_deps():                                                                                                                                                                   
89.55 backends.py(1149):                             if isinstance(l, build.SharedLibrary):                                                                                                                                                                                                                                                                                                   89.55 backends.py(1150):                                 ld_lib_path.add(os.path.join(self.environment.get_build_dir(), l.get_subdir()))
 --- modulename: environment, funcname: get_build_dir                                      
89.55 environment.py(782):         return self.build_dir                                                                                                                                       
 --- modulename: build, funcname: get_subdir                                                                                                                                                                                                                                                                                                                                                  
89.55 build.py(584):         return self.subdir         
 --- modulename: posixpath, funcname: join                                                 
89.55 <frozen posixpath>(76): 89.55 <frozen posixpath>(77):  --- modulename: posixpath, funcname: _get_sep                              
89.55 <frozen posixpath>(42): 89.55 <frozen posixpath>(45): 89.55 <frozen posixpath>(78): 89.55 <frozen posixpath>(79): 89.55 <frozen posixpath>(80): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(83): 89.55 <frozen posixpath>(85): 89.55 <frozen posixpath>(88): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(92): 89.55 backends.py(1148):                         for
 l in d.get_all_link_deps():                                                                                                                                                                   
89.55 backends.py(1149):                             if isinstance(l, build.SharedLibrary):                                                                                                                                                                                                                                                                                                   89.55 backends.py(1150):                                 ld_lib_path.add(os.path.join(self.environment.get_build_dir(), l.get_subdir()))
 --- modulename: environment, funcname: get_build_dir                                      
89.55 environment.py(782):         return self.build_dir                                                                                                                                       
 --- modulename: build, funcname: get_subdir                                                                                                                                                                                                                                                                                                                                                  
89.55 build.py(584):         return self.subdir         
 --- modulename: posixpath, funcname: join                                                 
89.55 <frozen posixpath>(76): 89.55 <frozen posixpath>(77):  --- modulename: posixpath, funcname: _get_sep                              
89.55 <frozen posixpath>(42): 89.55 <frozen posixpath>(45): 89.55 <frozen posixpath>(78): 89.55 <frozen posixpath>(79): 89.55 <frozen posixpath>(80): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(83): 89.55 <frozen posixpath>(85): 89.55 <frozen posixpath>(88): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(92): 89.55 backends.py(1148):                         for
 l in d.get_all_link_deps():                                                                                                                                                                   
89.55 backends.py(1149):                             if isinstance(l, build.SharedLibrary):                                                                                                                                                                                                                                                                                                   89.55 backends.py(1150):                                 ld_lib_path.add(os.path.join(self.environment.get_build_dir(), l.get_subdir()))
 --- modulename: environment, funcname: get_build_dir                                      
89.55 environment.py(782):         return self.build_dir                                                                                                                                       
 --- modulename: build, funcname: get_subdir                                                                                                                                                                                                                                                                                                                                                  
89.55 build.py(584):         return self.subdir         
 --- modulename: posixpath, funcname: join                                                 
89.55 <frozen posixpath>(76): 89.55 <frozen posixpath>(77):  --- modulename: posixpath, funcname: _get_sep                              
89.55 <frozen posixpath>(42): 89.55 <frozen posixpath>(45): 89.55 <frozen posixpath>(78): 89.55 <frozen posixpath>(79): 89.55 <frozen posixpath>(80): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(83): 89.55 <frozen posixpath>(85): 89.55 <frozen posixpath>(88): 89.55 <frozen posixpath>(82): 89.55 <frozen posixpath>(92): 89.55 backends.py(1148):                         for
 l in d.get_all_link_deps():                                                                                                                                                                   
89.55 backends.py(1149):                             if isinstance(l, build.SharedLibrary):                                                                                                                                                                                                                                                                                                   89.55 backends.py(1150):                                 ld_lib_path.add(os.path.join(self.environment.get_build_dir(), l.get_subdir()))
 --- modulename: environment, funcname: get_build_dir                                      
89.55 environment.py(782):         return self.build_dir                                                                                                                                       
 --- modulename: build, funcname: get_subdir                                                                                                                                                                                                                                                                                                                                                  
89.55 build.py(584):         return self.subdir         
 --- modulename: posixpath, funcname: join
anarazel commented 1 year ago

@dotnwat Can you provide any more specifics about your project? How many targets are there, what are there huge amounts of interdependencies?

The 150M calls to get_build_dir, get_subdir, join and 'set.add'

 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
...
150316869    8.414    0.000    8.414    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/environment.py:781(get_build_dir)
150316741    7.923    0.000    7.923    0.000 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/build.py:583(get_subdir)
150317917   96.161    0.000  144.483    0.000 <frozen posixpath>:71(join)
150316997    9.266    0.000    9.266    0.000 {method 'add' of 'set' objects}

plus the high cumtime in create_test_serialisation

        2   91.762   45.881  266.491  133.245 /home/nwatkins/.local/lib/python3.11/site-packages/mesonbuild/backend/backends.py:1087(create_test_serialisation)

strongly indicate all the time is spent in this loop: https://github.com/mesonbuild/meson/blob/b85ffbacb12701382da3404c9bd5aaf56e2c883f/mesonbuild/backend/backends.py#L1158-L1160

Which also explains why not using shared libraries makes things a lot faster.

I'd probably just stick a print(d, d.get_all_link_deps(), file=sys.stderr) in there and see if that tells us more.