DEBUG vs. non-DEBUG comparo (was Re: [perf-discuss] strange libmicro math)

[Dan Price]

[resend, fixing attachment]

Ok.  Attached is a preliminary DEBUG vs. non-DEBUG comparison; I
eliminated the one test which was very obviously misfiring.  It could be
that there are others which are also misbehaving.

For those not acquainted with what I'm measuring: there are two ways to
build the Solaris kernel: DEBUG (i.e. with various debugging checks
enabled, ASSERTs, etc), or non-DEBUG (i.e. go fast).

We're often asked "What is the overhead of running DEBUG?" to which the
answer is always "it depends on the workload"... and it does.  But I
thought it would be neat to get some measurement of how and why running
DEBUG might impact performance.

As a reminder: we consider benchmarking applications or perf. fixes
on DEBUG bits to be invalid in general.

If people care, I could post this comparo to the website as well.

        -dp

-- 
Daniel Price - Solaris Kernel Engineering - [EMAIL PROTECTED] - blogs.sun.com/dp

Title: multiview comparison

Preliminary DEBUG vs. non-DEBUG comparison; I eliminated the one test which was very obviously misfiring. It could be that there are others which are also misbehaving. For those not acquainted with what I'm measuring: there are two ways to build the Solaris kernel: DEBUG (i.e. with various debugging checks enabled, ASSERTs, etc), or non-DEBUG (i.e. go fast). We're often asked "What is the overhead of running DEBUG?" to which the answer is always "it depends on the workload"... and it does. But I thought it would be neat to get some measurement of how and why running DEBUG might impact performance. As a reminder: we consider benchmarking applications or perf. fixes on DEBUG bits to be invalid in general. Libmicro_# 0.3.0 0.3.0 Options -E -C 200 -L -S -W -E -C 200 -L -S -W Machine_name xanadu xanadu OS_name SunOS SunOS OS_release 5.11 5.11 OS_build snv_20 non-DEBUG snv_20 DEBUG Processor i86pc i86pc #CPUs 1 1 CPU_MHz 2100MHz 2100MHz CPU_NAME AMD Athlon(tm) 64 Processor 3200+ AMD Athlon(tm) 64 Processor 3200+ IP_address 129.146.228.194 129.146.228.194 Run_by dp dp Date 08/17/05 18:15 08/16/05 15:01 Compiler cc cc Compiler Ver. cc: Sun C 5.7 Patch 117837-04 cc: Sun C 5.7 Patch 117837-04 sizeof(long) 4 4 extra_CFLAGS [none] [none] TimerRes 1 nsecs 1 nsecs BENCHMARK USECS USECS [percentage] bind 20.16695 55.81066[ -176.7%] c_cond_1 0.65550 0.63050[ +4.0%] c_cond_10 62.07450 73.30700[-18.1%] c_cond_200 1767.30100 2045.68850[-15.8%] c_fcntl_1 3.81400 6.78900[-78.0%] c_fcntl_10 106.74500 173.69900[-62.7%] c_fcntl_200 7593.39300 9657.01350[-27.2%] c_lockf_1 3.89900 7.00300[-79.6%] c_lockf_10 100.43050 168.17950[-67.5%] c_lockf_200 4064.15050 6652.02350[-63.7%] c_mutex_1 0.22150 0.22550[ -1.8%] c_mutex_10 53.29750 64.13500[-20.3%] c_mutex_200 1541.22700 2072.50250[-34.5%] cachetocache 0.02736 0.02938[ -7.4%] chdir_tmp 3.57600 5.56700[-55.7%] chdir_usr 2.37700 2.63800[-11.0%] chgetwd_tmp 7.64600 15.49000[ -102.6%] chgetwd_usr 6.11300 11.45300[-87.4%] close_bad 0.51119 0.61156[-19.6%] close_tcp 6.67647 79.15516[-1085.6%] close_tmp 0.47597 0.94172[-97.9%] close_usr 0.48394 0.93425[-93.1%] close_zero 0.51847 1.00087[-93.0%] conn_accept 8.46902 22.47740[ -165.4%] conn_connect 11.92687 117.23388[ -882.9%] connection 38.55261 238.23842[ -518.0%] dup 0.45695 0.52914[-15.8%] exec 650.43560 1032.13220[-58.7%] exit_10 383.60020 733.53940[-91.2%] exit_100 335.71996 628.70487[-87.3%] exit_1000 345.39208 734.19470[ -112.6%] exit_10_nolibc 287.80270 611.84270[ -112.6%] exp 0.08250 0.08170[ +1.0%] fcntl_ndelay 0.31975 0.40650[-27.1%] fcntl_tmp 0.28700 0.40000[-39.4%] fcntl_usr 0.29100 0.40000[-37.5%] file_lock 1.40100 2.40200[-71.4%] fork_10 450.53780 859.84380[-90.8%] fork_100 287.50531 676.83980[ -135.4%] fork_1000 509.43544 900.29370[-76.7%] getcontext 0.64940 0.80910[-24.6%] getenv 0.33510 0.33500[ +0.0%] getenvT2 0.97410 1.02350[ -5.1%] getpeername 0.41600 0.53100[-27.6%] getpid 0.15250 0.23470[-53.9%] getrusage 0.47810 0.49130[ -2.8%] getsockname 0.41400 0.53500[-29.2%] gettimeofday 0.17965 0.18250[ -1.6%] isatty_no 0.59825 0.74175[-24.0%] isatty_yes 2.06715 7.10120[ -243.5%] listen 2.13295 31.49399[-1376.5%] localtime_r 0.73380 0.74610[ -1.7%] log 0.07550 0.07550[ +0.0%] longjmp 0.00810 0.00810[ +0.0%] lrand48 0.09930 0.10150[ -2.2%] lseek_t8k 0.33800 0.38200[-13.0%] lseek_u8k 0.33950 0.38050[-12.1%] mallocT2_10 0.91340 1.03120[-12.9%] mallocT2_100 1.02690 1.12800[ -9.8%] mallocT2_100k 1.03870 1.14460[-10.2%] mallocT2_10k 1.03300 1.14170[-10.5%] mallocT2_1k 1.02630 1.12790[ -9.9%] malloc_10 0.22690 0.26130[-15.2%] malloc_100 0.28015 0.30830[-10.0%] malloc_100k 0.28160 0.30960[ -9.9%] malloc_10k 0.27995 0.30810[-10.1%] malloc_1k 0.27995 0.30805[-10.0%] memcpy_10 0.02220 0.02220[ +0.0%] memcpy_10k 0.95400 0.95800[ -0.4%] memcpy_10m 7056.49600 7179.93900[ -1.7%] memcpy_1k 0.12200 0.12150[ +0.4%] memcpy_1m 436.53000 505.48100[-15.8%] memrand 0.05172 0.05172[ +0.0%] memsetP2_10m 6621.03570 6624.18080[ -0.0%] memset_10 0.01670 0.01670[ +0.0%] memset_10k 0.63960 0.63960[ +0.0%] memset_10m 3309.49180 3311.13350[ -0.0%] memset_1k 0.09100 0.09100[ +0.0%] memset_1m 330.12870 328.92380[ +0.4%] memset_256 0.03620 0.03620[ +0.0%] memset_256_u 0.05150 0.05150[ +0.0%] memset_4k 0.27390 0.27390[ +0.0%] memset_4k_uc 0.28500 0.28500[ +0.0%] mktime 8.58100 8.72300[ -1.7%] mktimeT2 20.96100 21.44300[ -2.3%] mmap_a128k 1.04500 1.91500[-83.3%] mmap_a8k 1.03600 1.90000[-83.4%] mmap_ra128k 129.36400 181.28600[-40.1%] mmap_ra8k 10.27000 16.26200[-58.3%] mmap_rt128k 63.56100 81.48400[-28.2%] mmap_rt8k 5.45600 9.23600[-69.3%] mmap_ru128k 22.36000 32.15800[-43.8%] mmap_ru8k 4.79400 7.73500[-61.3%] mmap_rz128k 129.52900 182.17300[-40.6%] mmap_rz8k 10.71400 16.86600[-57.4%] mmap_t128k 1.19300 2.15000[-80.2%] mmap_t8k 1.16700 2.09300[-79.3%] mmap_u128k 1.31800 2.34300[-77.8%] mmap_u8k 1.30200 2.34900[-80.4%] mmap_wa128k 128.32800 182.58300[-42.3%] mmap_wa8k 10.07700 16.30300[-61.8%] mmap_wt128k 207.47200 275.78300[-32.9%] mmap_wt8k 13.36200 20.22700[-51.4%] mmap_wu128k 216.51800 294.44500[-36.0%] mmap_wu8k 14.18200 21.88400[-54.3%] mmap_wz128k 127.71000 181.15700[-41.9%] mmap_wz8k 10.68300 16.77100[-57.0%] mmap_z128k 1.21800 2.07600[-70.4%] mmap_z8k 1.24000 2.06100[-66.2%] mprot_tw4m 2937.54500 3560.22100[-21.2%] mprot_twz8k 5.98900 7.67200[-28.1%] mprot_wz128k 0.66000 0.72000[ -9.1%] mprot_wz8k 0.62900 0.64400[ -2.4%] mprot_z128k 0.69100 0.72100[ -4.3%] mprot_z8k 0.59500 0.63700[ -7.1%] mutex_T2 3.25900 3.79300[-16.4%] mutex_mt 0.07610 0.06800[+11.9%] mutex_st 0.05800 0.06080[ -4.8%] open_tmp 2.05963 5.21819[ -153.4%] open_usr 1.68584 2.64721[-57.0%] open_zero 3.92667 11.46377[ -191.9%] pipe_pmp1 461.82400 749.70400[-62.3%] pipe_pmp4k 477.60200 841.24800[-76.1%] pipe_pmt1 15.29400 23.18700[-51.6%] pipe_pmt4k 16.86500 72.27000[ -328.5%] pipe_pst1 1.19200 3.22100[ -170.2%] pipe_pst4k 1.67200 26.40100[-1479.0%] pipe_smp1 470.33900 836.85800[-77.9%] pipe_smp4k 485.98800 923.89100[-90.1%] pipe_smt1 20.93200 32.35000[-54.5%] pipe_smt4k 23.04200 79.64500[ -245.7%] pipe_sst1 3.80300 7.99000[ -110.1%] pipe_sst4k 4.75100 30.43800[ -540.7%] pipe_tmp1 467.29700 882.01000[-88.7%] pipe_tmp4k 484.31200 971.47400[ -100.6%] pipe_tmt1 21.24300 34.79800[-63.8%] pipe_tmt4k 23.54400 84.16300[ -257.5%] pipe_tst1 3.97000 7.76900[-95.7%] pipe_tst4k 4.88000 31.21700[ -539.7%] poll_10 0.55800 6.36600[-1040.9%] poll_100 1.03000 28.80800[-2696.9%] poll_1000 6.22600 325.22300[-5123.6%] poll_w10 0.87400 6.92600[ -692.4%] poll_w100 3.58700 31.90000[ -789.3%] poll_w1000 37.75000 370.52700[ -881.5%] pread_t100k 27.91500 30.96100[-10.9%] pread_t10k 1.80200 2.12800[-18.1%] pread_t1k 0.80400 1.06700[-32.7%] pread_u100k 26.29800 29.48900[-12.1%] pread_u10k 2.02000 2.29900[-13.8%] pread_u1k 1.00900 1.28900[-27.8%] pread_z100k 13.23900 13.44900[ -1.6%] pread_z10k 0.80300 1.04900[-30.6%] pread_z1k 0.52900 0.74800[-41.4%] pread_zw100k 13.53100 13.78800[ -1.9%] pthread_128 20.96154 48.92859[ -133.4%] pthread_32 11.50369 28.69069[ -149.4%] pthread_512 25.46025 56.06099[ -120.2%] pthread_8 6.17237 11.88600[-92.6%] pwrite_n100k 0.51900 0.62300[-20.0%] pwrite_n10k 0.53500 0.62300[-16.4%] pwrite_n1k 0.51900 0.62300[-20.0%] pwrite_t100k 37.43300 44.08900[-17.8%] pwrite_t10k 2.57200 3.57200[-38.9%] pwrite_t1k 0.83900 1.15800[-38.0%] pwrite_u100k 37.78100 43.70900[-15.7%] pwrite_u10k 3.37300 4.64700[-37.8%] pwrite_u1k 1.37100 1.87500[-36.8%] read_t100k 29.03200 29.73700[ -2.4%] read_t10k 1.83400 2.25300[-22.8%] read_t1k 0.81100 1.01700[-25.4%] read_u100k 26.00300 29.30500[-12.7%] read_u10k 1.82100 2.34100[-28.6%] read_u1k 1.01300 1.23600[-22.0%] read_z100k 13.18600 13.34200[ -1.2%] read_z10k 0.90200 1.02200[-13.3%] read_z1k 0.61500 0.72600[-18.0%] read_zw100k 13.46900 13.60800[ -1.0%] realpath_tmp 4.21100 9.24900[ -119.6%] realpath_usr 3.13000 6.40200[ -104.5%] recurse 0.90529 0.90529[ +0.0%] scasecmp_10 0.40550 0.40800[ -0.6%] scasecmp_1k 49.69800 49.66400[ +0.1%] select_10 0.68300 6.67200[ -876.9%] select_100 2.05500 30.47700[-1383.1%] select_1000 15.85100 335.99800[-2019.7%] select_w10 1.13000 6.86400[ -507.4%] select_w100 5.75300 32.41300[ -463.4%] select_w1000 57.31000 391.89000[ -583.8%] semop 0.77700 1.31800[-69.6%] setcontext 2.21300 2.57000[-16.1%] setsockopt 2.27200 6.72400[ -196.0%] sigaction 0.46100 0.67200[-45.8%] siglongjmp 1.01320 1.13920[-12.4%] signal 39.96100 60.09700[-50.4%] sigprocmask 6.27200 7.09100[-13.1%] socket_i 4.72220 28.97201[ -513.5%] socket_u 4.30675 29.40109[ -582.7%] socketpair 34.40102 203.11159[ -490.4%] stat_tmp 1.91500 3.93600[ -105.5%] stat_usr 1.45000 1.85000[-27.6%] strchr_10 0.01775 0.01560[+13.8%] strchr_1k 6.28700 6.26300[ +0.4%] strcmp_10 0.02570 0.02520[ +2.0%] strcmp_1k 5.17300 5.16700[ +0.1%] strcpy_10 0.01360 0.01270[ +7.1%] strcpy_1k 3.84400 3.82700[ +0.4%] strftime 19.25500 19.24800[ +0.0%] strlen_10 0.01610 0.01415[+13.8%] strlen_1k 3.84900 3.82600[ +0.6%] strtol 0.08910 0.08900[ +0.1%] system 848.61500 1591.25600[-87.5%] time 0.99200 1.54000[-55.2%] times 4.06600 4.67200[-14.9%] unmap_a128k 0.79800 1.85600[ -132.6%] unmap_a8k 0.72400 1.75500[ -142.4%] unmap_ra128k 50.53300 78.48800[-55.3%] unmap_ra8k 5.94500 10.13400[-70.5%] unmap_rt128k 31.69100 36.38000[-14.8%] unmap_rt8k 3.79300 6.05900[-59.7%] unmap_ru128k 31.83900 36.19300[-13.7%] unmap_ru8k 4.00500 5.87800[-46.8%] unmap_rz128k 49.08000 79.10200[-61.2%] unmap_rz8k 5.90200 10.04400[-70.2%] unmap_t128k 0.84000 2.00600[ -138.8%] unmap_t8k 0.76000 1.88100[ -147.5%] unmap_u128k 0.98700 1.97600[ -100.2%] unmap_u8k 0.89800 1.88700[ -110.1%] unmap_wa128k 51.08700 78.86400[-54.4%] unmap_wa8k 5.86700 10.27300[-75.1%] unmap_wt128k 52.18600 79.49200[-52.3%] unmap_wt8k 6.24900 10.41000[-66.6%] unmap_wu128k 52.38300 80.02800[-52.8%] unmap_wu8k 6.35400 10.68200[-68.1%] unmap_wz128k 50.70200 78.20700[-54.2%] unmap_wz8k 5.92800 10.16500[-71.5%] unmap_z128k 0.81300 1.86400[ -129.3%] unmap_z8k 0.72700 1.77600[ -144.3%] write_n100k 0.49500 0.64700[-30.7%] write_n10k 0.49500 0.66500[-34.3%] write_n1k 0.49500 0.65600[-32.5%] write_t100k 81.66700 80.81800[ +1.1%] write_t10k 5.00600 5.72100[-14.3%] write_t1k 1.11900 1.39700[-24.8%] write_u100k 88.18300 89.21100[ -1.2%] write_u10k 5.79800 6.79100[-17.1%] write_u1k 1.56400 2.03400[-30.1%] writev_n100k 0.68500 0.83200[-21.5%] writev_n10k 0.68400 0.83200[-21.6%] writev_n1k 0.69200 0.82800[-19.7%] writev_t100k 847.38100 829.68500[ +2.1%] writev_t10k 83.12800 81.40200[ +2.1%] writev_t1k 5.85400 5.98000[ -2.2%] writev_u100k 926.77600 928.70000[ -0.2%] writev_u10k 88.42300 87.24100[ +1.4%] writev_u1k 6.54000 7.12700[ -9.0%]

_______________________________________________
perf-discuss mailing list
perf-discuss@opensolaris.org