From owner-freebsd-performance@FreeBSD.ORG Mon Jun 2 11:25:40 2008 Return-Path: Delivered-To: freebsd-performance@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 3DFD11065670 for ; Mon, 2 Jun 2008 11:25:40 +0000 (UTC) (envelope-from brde@optusnet.com.au) Received: from mail11.syd.optusnet.com.au (mail11.syd.optusnet.com.au [211.29.132.192]) by mx1.freebsd.org (Postfix) with ESMTP id C37338FC16 for ; Mon, 2 Jun 2008 11:25:39 +0000 (UTC) (envelope-from brde@optusnet.com.au) Received: from c220-239-252-11.carlnfd3.nsw.optusnet.com.au (c220-239-252-11.carlnfd3.nsw.optusnet.com.au [220.239.252.11]) by mail11.syd.optusnet.com.au (8.13.1/8.13.1) with ESMTP id m52BPFcQ009707 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Mon, 2 Jun 2008 21:25:22 +1000 Date: Mon, 2 Jun 2008 21:25:15 +1000 (EST) From: Bruce Evans X-X-Sender: bde@delplex.bde.org To: Claus Guttesen In-Reply-To: Message-ID: <20080602205953.X3162@delplex.bde.org> References: <2B465A44-2578-4675-AA17-EBE17A072017@chittenden.org> MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed Cc: freebsd-performance@freebsd.org, Sean Chittenden Subject: Re: Micro-benchmark for various time syscalls... X-BeenThere: freebsd-performance@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Performance/tuning List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 02 Jun 2008 11:25:40 -0000 On Mon, 2 Jun 2008, Claus Guttesen wrote: >> % ./bench_time 9079882 | sort -rnk1 >> Timing micro-benchmark. 9079882 syscall iterations. >> Avg. us/call Elapsed Name >> 9.322484 84.647053 gettimeofday(2) >> 8.955324 81.313291 time(3) >> 8.648315 78.525684 clock_gettime(2/CLOCK_REALTIME) >> 8.598495 78.073325 clock_gettime(2/CLOCK_MONOTONIC) >> 0.674194 6.121600 clock_gettime(2/CLOCK_PROF) >> 0.648083 5.884515 clock_gettime(2/CLOCK_VIRTUAL) >> 0.330556 3.001412 clock_gettime(2/CLOCK_REALTIME_FAST) >> 0.306514 2.783111 clock_gettime(2/CLOCK_SECOND) >> 0.262788 2.386085 clock_gettime(2/CLOCK_MONOTONIC_FAST) In previous mail, I said that these were very slow. > rozetta~/devel/c%>sysctl hw.model > hw.model: Intel(R) Xeon(R) CPU E5345 @ 2.33GHz > > rozetta~/devel/c%>./bench_time 9079882 | sort -rnk1 > Timing micro-benchmark. 9079882 syscall iterations. > Avg. us/call Elapsed Name > 1.405469 12.761494 clock_gettime(2/CLOCK_REALTIME) > 1.313101 11.922799 time(3) > 1.305518 11.853953 clock_gettime(2/CLOCK_MONOTONIC) > 1.303947 11.839681 gettimeofday(2) > 0.442908 4.021557 clock_gettime(2/CLOCK_PROF) > 0.436484 3.963223 clock_gettime(2/CLOCK_VIRTUAL) > 0.217718 1.976851 clock_gettime(2/CLOCK_MONOTONIC_FAST) > 0.215264 1.954571 clock_gettime(2/CLOCK_REALTIME_FAST) > 0.211779 1.922932 clock_gettime(2/CLOCK_SECOND) These seem about right for a normal untuned ~2GHz system: - there is a syscall overhead of about 200 nsec - the hardware parts of the ACPI (?) timecounter are very slow, so they add 1100 nsec - anomalous extra 100 nsec for CLOCK_REALTIME. CLOCK_REALTIME does less than gettimeofday(). - CLOCK_PROF and CLOCK_VIRTUAL use the slow function calcru() in the kernel. This apparently takes about the same time as a syscall. calcru() uses cpu_ticks() (which normally uses the TSC on i386 and amd64) to determine the time spent since the thread was last context switched, so it is more accurate than CLOCK_REALTIME_FAST but less accurate than CLOCK_REALTIME; using the TSC makes it faster than a non-TSC timecounter. calcru() still seems to have broken accounting for the current timeslice in other running threads in the process. > gettimeofday is 6 times slower on this system, 28 times slower on your system. 1.epsilon times slower on my system :-). Bruce