From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754549Ab1AKITe (ORCPT ); Tue, 11 Jan 2011 03:19:34 -0500 Received: from straum.hexapodia.org ([207.7.131.186]:43443 "EHLO straum.hexapodia.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751405Ab1AKIT2 (ORCPT ); Tue, 11 Jan 2011 03:19:28 -0500 Date: Tue, 11 Jan 2011 00:19:28 -0800 From: Andy Isaacson To: linux-kernel@vger.kernel.org Subject: mmap/munmap 20ms latencies, 2.6.37 Message-ID: <20110111081928.GL18828@hexapodia.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline X-GPG-Fingerprint: 1914 0645 FD53 C18E EEEF C402 4A69 B1F3 68D2 A63F X-GPG-Key-URL: http://web.hexapodia.org/~adi/gpg.txt X-Domestic-Surveillance: money launder bomb tax evasion User-Agent: Mutt/1.5.18 (2008-05-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org I'm seeing high latencies (up to 20 ms with no sign of CPU contention) from mmap/munmap, using the enclosed test program on various Core i7 processors. For example on a "Intel(R) Core(TM) i7 CPU 930@2.80GHz" with 12GB RAM running 0c21e3a, % /tmp/munmapslow -t 6 ... [1294732507.539851] <8636> free(0x7f2608f08000) len=57344 took 4041 us [1294732507.559841] <8632> free(0x7f260e810000) len=32768 took 8032 us [1294732507.570254] <8632> malloc(81920) took 2452 us [1294732507.583834] <8635> malloc(73728) took 8035 us [1294732507.595840] <8631> malloc(65536) took 4048 us [1294732507.599838] <8635> malloc(45056) took 8041 us [1294732507.603834] <8631> malloc(20480) took 4029 us ... [1294732510.603845] <8634> realloc(0x756170, 23408) took 4035 us [1294732510.647850] <8634> malloc(73728) took 28047 us [1294732510.675831] <8631> malloc(53248) took 28028 us [1294732510.731835] <8631> malloc(81920) took 28035 us ... [1294732543.685480] <8633> 5244182 heap events, 3739 allocated, 4425 max, 153.57 MiB total [1294732543.685503] <8633> 78060.59 ms total for 5244182 allocations (15 us per allocation) [1294732543.685509] <8633> 13779.82 ms total for 5240443 frees (3 us per free) Most of the time, mmap takes about 15 us and munmap takes less than 5 us for these small buffers (<20 pages). Of course if a significant background job fires, a lot of "slow operations" are seen; but I'm seeing cases where preemption doesn't appear to be the cause. (I suppose I could parse /proc/self/sched to confirm this...) I'll try trace-cmd tomorrow, but I wonder if anyone already knows what's going on? (As you may guess, this is an attempt to isolate a problem seen in a larger system that's not easy to reduce to a simple testcase. We're seeing a 3x higher system time reported via munin than previously, even though the CPUs went from 20%-40% idle to 100% pegged and overall throughput *dropped* somewhat due to being CPU limited. It's not clear what changed to trigger the increased system time -- but munmap popped out of strace -c.) Thanks, -andy /* * Attempt to reproduce munmap slowness seen on * 2.6.35-23-generic * Intel(R) Xeon(R) CPU E5504 @ 2.00GHz * with HT turned on. * * strace -c shows that munmap is taking up to 11 ms per call and * that's where we are spending 95% of our time. * * Plan for testcase: * * fork N processes. * In each process, repeatedly allocate and free various buffer sizes. */ #include #include #include #include #include #include #include #include #include #define MAX_TIME (1000 * 1e-6) typedef unsigned int u32; static int pgsz; double rtc(void) { struct timeval t; gettimeofday(&t, 0); return t.tv_sec + t.tv_usec/1e6; } void die(char *fmt, ...) __attribute__((noreturn)); void die(char *fmt, ...) { va_list ap; fprintf(stderr, "[%.6f] <%d> ", rtc(), (int)getpid()); va_start(ap, fmt); vfprintf(stderr, fmt, ap); va_end(ap); exit(1); } void msg(char *fmt, ...) { va_list ap; printf("[%.6f] <%d> ", rtc(), (int)getpid()); va_start(ap, fmt); vfprintf(stdout, fmt, ap); va_end(ap); } /* * returns a random integer chosen from a uniform distribution on [0, range). */ u32 myrand(u32 range) { u32 x, mask; int i, MAX = 1000; if (range == 1) return 0; mask = range - 1; while (mask & (mask - 1)) mask &= (mask - 1); mask |= (mask - 1); for (i = 0; i < MAX; i++) { x = lrand48() & mask; if (x < range) return x; } die("myrand failed after %d iter, range = %lld mask = 0x%llx x = 0x%llx\n", i, (long long)range, (long long) mask, (long long)x); } static void **heap; static int num_heap, max_num_heap; static long long totsz; static double elapsed_alloc, elapsed_free; int num_alloc, num_free; void heap_stats(void) { msg("%d heap events, %d allocated, %d max, %.2f MiB total\n", num_alloc, num_heap, max_num_heap, totsz / 1024. / 1024); msg("%.2f ms total for %d allocations (%.0f us per allocation)\n", elapsed_alloc * 1e3, num_alloc, elapsed_alloc * 1e6 / num_alloc); msg("%.2f ms total for %d frees (%.0f us per free)\n", elapsed_free * 1e3, num_free, elapsed_free * 1e6 / num_alloc); } void *myalloc(size_t sz) { double t0, t1, e; void *p; t0 = rtc(); p = mmap(0, sz, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0); if (p == MAP_FAILED) die("mmap(%d): %s\n", (int)sz, strerror(errno)); t1 = rtc(); e = t1 - t0; if (e > MAX_TIME) msg("malloc(%d) took %.0f us\n", (int)sz, e * 1e6); elapsed_alloc += e; num_alloc++; return p; } void myfree(void *p) { double t0, t1, e; int sz = *(int *)p; t0 = rtc(); munmap(p, sz); t1 = rtc(); e = t1 - t0; if (e > MAX_TIME) msg("free(%p) len=%d took %.0f us\n", p, sz, e * 1e6); elapsed_free += e; num_free++; } void heap_allocate(int sz) { void *n; void **h2; double t1, t2, e; n = myalloc(sz); if (!n) die("malloc(%d) failed.\n", sz); *(int *)n = sz; t1 = rtc(); h2 = realloc(heap, sizeof(*heap) * ++num_heap); t2 = rtc(); e = t2 - t1; if (!h2) die("realloc(%p, %d) failed.\n", heap, (int)(sizeof(*heap) * num_heap)); if ((t2 - t1) > MAX_TIME) msg("realloc(%p, %d) took %.0f us\n", heap, (int)(sizeof(*heap) * num_heap), e * 1e6); if (num_heap > max_num_heap) max_num_heap = num_heap; totsz += sz; h2[num_heap-1] = n; heap = h2; } void heap_free(void) { int i; if (num_heap <= 0) return; i = myrand(num_heap--); totsz -= *(int *)heap[i]; if (heap[i]) myfree(heap[i]); for (; i < num_heap; i++) heap[i] = heap[i+1]; } void send_message(void) { } void receive_message(void) { } void worker(void) { long long i; long long counts[4] = { 0 }; int ITERCOUNT = 10 * 1024 * 1024; for (i=0; ; i++) { int action = myrand(4); if (i < 10000 && action == 1 && myrand(2) == 1) action = 0; counts[action]++; switch(action) { case 0: heap_allocate(pgsz * (myrand(20) + 1)); break; case 1: heap_free(); break; case 2: send_message(); break; case 3: receive_message(); break; } if (i % ITERCOUNT == ITERCOUNT - 1) { heap_stats(); } } } void usage(const char *cmd) { die("Usage: %s [-t numthreads]\n", cmd); } int main(int argc, char **argv) { int c, i; int nproc = sysconf(_SC_NPROCESSORS_ONLN); pgsz = getpagesize(); while ((c = getopt(argc, argv, "t:")) != EOF) { switch (c) { case 't': nproc = strtol(optarg, 0, 0); break; default: usage(argv[0]); } } printf("forking %d children\n", nproc); for (i=0; i < nproc; i++) { switch(fork()) { case -1: die("fork: %s\n", strerror(errno)); case 0: /* child */ worker(); exit(0); default: /* parent */ /* nothing */ break; } } for (i=0; i < nproc; i++) { int x, p; p = wait(&x); msg("child %d exited\n", p); } return 0; }