From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 97348 invoked by alias); 8 Dec 2015 10:51:13 -0000 Mailing-List: contact cygwin-help@cygwin.com; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner@cygwin.com Mail-Followup-To: cygwin@cygwin.com Received: (qmail 97296 invoked by uid 89); 8 Dec 2015 10:51:12 -0000 Authentication-Results: sourceware.org; auth=none X-Virus-Found: No X-Spam-SWARE-Status: No, score=0.0 required=5.0 tests=AWL,BAYES_50,KAM_LAZY_DOMAIN_SECURITY autolearn=no version=3.3.2 X-HELO: m0.truegem.net Received: from m0.truegem.net (HELO m0.truegem.net) (69.55.228.47) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with (AES256-SHA encrypted) ESMTPS; Tue, 08 Dec 2015 10:51:10 +0000 Received: (from daemon@localhost) by m0.truegem.net (8.12.11/8.12.11) id tB8Ap81D036840 for ; Tue, 8 Dec 2015 02:51:08 -0800 (PST) (envelope-from mark@maxrnd.com) Received: from 76-217-5-154.lightspeed.irvnca.sbcglobal.net(76.217.5.154), claiming to be "[192.168.1.100]" via SMTP by m0.truegem.net, id smtpdRDlu99; Tue Dec 8 02:51:06 2015 Subject: Re: Cygwin multithreading performance To: cygwin@cygwin.com References: <564E3017.90205@maxrnd.com> <5650379B.4030405@maxrnd.com> <20151121105301.GE2755@calimero.vinschen.de> <5652C402.7040006@maxrnd.com> <24780-1448274431-7444@sneakemail.com> <5653B52B.5000804@maxrnd.com> <20151126093427.GJ2755@calimero.vinschen.de> <5656DDEF.9070603@maxrnd.com> <5662C199.7040906@maxrnd.com> <566367C8.5020703@maxrnd.com> <5663EB9A.40002@maxrnd.com> From: Mark Geisert Message-ID: <5666B61F.9050209@maxrnd.com> Date: Tue, 08 Dec 2015 10:51:00 -0000 User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:42.0) Gecko/20100101 Firefox/42.0 SeaMonkey/2.39 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-SW-Source: 2015-12/txt/msg00099.txt.bz2 (Maybe cygwin-developers is a better list for this? It's pretty obscure.) Here are some mutex lock stats I've been talking about providing. These are from the OP's original testcase 'git repack -a -f' running over a clone of the newlib-cygwin source tree. Run on a 2-core, 4-HT machine under Windows 7 x64. I'm running a slightly modified cygwin1.dll that has 3 one-line mods to thread.cc. I feed an strace output file through an awk script and a C program to produce the output below. The first display is a summary showing all mutexes with latency buckets and counts for each thread and each mutex. The second display shows just the last two mutexes but also shows the count of locks and unlocks from each source line. You can see most mutexes have all their latencies <= 1 usec, but there are some that have a spectrum of latencies reaching above 1000 usecs == 1 msec. I'm defining latency as the difference in usecs between a timestamp taken on entry to pthread_mutex::lock and the timestamp appearing in the strace output for that ::lock operation when '--mask=pthread' is specified. I'm considering adding the tools that produced these displays to the cygutils package. I'm unsure if the cygwin1.dll mods I've made locally should be shipped generally; I don't know how much extra CPU they use, if any. ..mark ======== first display ======== *** processes present *** pid 4908: git pid 7020: git *** threads present *** lock latency buckets: <=1 <=10 <=100 <=1000 >1000 tid main 0: lks 269960, ulks 269960, 269416 54 182 128 180 tid main 1: lks 6307, ulks 6307, 6304 1 2 0 0 tid 1216: lks 196941, ulks 196941, 84899 5045 91669 13914 1414 tid 4560: lks 197203, ulks 197203, 70033 4165 110333 11442 1230 tid 7840: lks 68984, ulks 68984, 34160 1389 25783 5685 1967 tid 9076: lks 166308, ulks 166308, 81715 2097 72009 8805 1682 *** mutexes present *** lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/01802F30E8 lks 0, ulks 0, 0 0 0 0 0 mtx 4908/0600000010 lks 9, ulks 9, 8 1 0 0 0 mtx 4908/0600000108 lks 179394, ulks 179394, 179361 18 14 0 1 mtx 4908/0600000160 lks 1, ulks 1, 1 0 0 0 0 mtx 4908/06000180E8 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/06000180E8 lks 4182, ulks 4182, 4180 0 2 0 0 mtx 4908/0600018140 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/0600018140 lks 1, ulks 1, 1 0 0 0 0 mtx 4908/0600028518 lks 18, ulks 18, 18 0 0 0 0 mtx 4908/0600038B60 lks 88002, ulks 88002, 87957 30 15 0 0 lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/0600038EB0 lks 194, ulks 194, 194 0 0 0 0 mtx 4908/0600039010 lks 6, ulks 6, 6 0 0 0 0 mtx 4908/06000390A0 lks 6, ulks 6, 6 0 0 0 0 mtx 7020/0600039A20 lks 6, ulks 6, 6 0 0 0 0 mtx 4908/060003A280 lks 1, ulks 1, 1 0 0 0 0 mtx 7020/060003A280 lks 8, ulks 8, 8 0 0 0 0 mtx 4908/060003A308 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/060003A308 lks 6, ulks 6, 6 0 0 0 0 mtx 4908/060003A370 lks 0, ulks 0, 0 0 0 0 0 mtx 4908/060003A3B0 lks 0, ulks 0, 0 0 0 0 0 lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/060003A428 lks 0, ulks 0, 0 0 0 0 0 mtx 4908/060003A468 lks 0, ulks 0, 0 0 0 0 0 mtx 4908/060003A940 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/060003A940 lks 26, ulks 26, 26 0 0 0 0 mtx 7020/060003AC90 lks 194, ulks 194, 194 0 0 0 0 mtx 7020/060003ADF0 lks 6, ulks 6, 6 0 0 0 0 mtx 4908/0600051B30 lks 1, ulks 1, 1 0 0 0 0 mtx 4908/0600051E20 lks 6, ulks 6, 6 0 0 0 0 mtx 7020/0600053A00 lks 920, ulks 920, 920 0 0 0 0 mtx 4908/0600053B20 lks 920, ulks 920, 920 0 0 0 0 lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/0600062008 lks 14, ulks 14, 14 0 0 0 0 mtx 4908/06000621D0 lks 2, ulks 2, 2 0 0 0 0 mtx 4908/06000625B0 lks 6, ulks 6, 6 0 0 0 0 mtx 4908/0600063B90 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/0600063B90 lks 2, ulks 2, 2 0 0 0 0 mtx 4908/0600063BE0 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/0600063BE0 lks 5, ulks 5, 5 0 0 0 0 mtx 4908/0600063C30 lks 0, ulks 0, 0 0 0 0 0 mtx 7020/0600063C30 lks 2, ulks 2, 2 0 0 0 0 mtx 7020/0600063C80 lks 4, ulks 4, 4 0 0 0 0 lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 7020/0600076500 lks 920, ulks 920, 920 0 0 0 0 mtx 4908/0600114120 lks 15, ulks 15, 9 2 4 0 0 mtx 4908/060013EE78 lks 658, ulks 658, 446 17 189 6 0 mtx 4908/060026DE50 lks 12, ulks 12, 4 1 6 1 0 mtx 4908/06002A00F0 lks 155066, ulks 155066, 66359 4395 78895 4742 675 mtx 4908/06006628D0 lks 4, ulks 4, 4 0 0 0 0 mtx 4908/06007217B0 lks 23, ulks 23, 23 0 0 0 0 mtx 4908/0600784C70 lks 1529, ulks 1529, 1285 39 195 10 0 mtx 7020/0600837A80 lks 13, ulks 13, 13 0 0 0 0 mtx 4908/0600A081E8 lks 10, ulks 10, 9 1 0 0 0 lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/0600A08228 lks 10, ulks 10, 5 3 2 0 0 mtx 4908/0600A082A8 lks 8, ulks 8, 6 0 2 0 0 mtx 4908/0600A082E8 lks 8, ulks 8, 3 0 5 0 0 mtx 4908/0600A08368 lks 8, ulks 8, 5 0 3 0 0 mtx 4908/0600A083A8 lks 8, ulks 8, 3 0 4 1 0 mtx 4908/0600D0A5B0 lks 2, ulks 2, 2 0 0 0 0 mtx 4908/0600F35670 lks 8, ulks 8, 8 0 0 0 0 mtx 4908/0600FA6860 lks 154745, ulks 154745, 56092 3217 64883 25435 5118 mtx 4908/060157A3B8 lks 580, ulks 580, 410 11 154 5 0 mtx 4908/060157E568 lks 4, ulks 4, 4 0 0 0 0 lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/060157E5A8 lks 4, ulks 4, 2 0 2 0 0 mtx 4908/06015B1AD0 lks 12, ulks 12, 3 0 7 2 0 mtx 4908/06019741E8 lks 259, ulks 259, 186 2 54 16 1 mtx 4908/0601974228 lks 259, ulks 259, 27 0 45 63 124 mtx 4908/0602076490 lks 6, ulks 6, 2 0 3 1 0 mtx 7020/0602874000 lks 12, ulks 12, 11 1 0 0 0 mtx 4908/060345CAB0 lks 1, ulks 1, 1 0 0 0 0 mtx 4908/060347FE48 lks 316, ulks 316, 246 13 54 3 0 mtx 4908/0603498600 lks 316825, ulks 316825, 146254 4986 155345 9686 554 mtx 4908/06034C8E68 lks 436, ulks 436, 324 14 95 3 0 ======== second display ======== lock latency buckets: <=1 <=10 <=100 <=1000 >1000 mtx 4908/0603498600 lks 316825, ulks 316825, 146254 4986 155345 9686 554 caller 0x0100455269, count 196769, L, /usr/src/git/builtin/pack-objects.c:1695 caller 0x01004552C4, count 15148, U, /usr/src/git/builtin/pack-objects.c:1705 caller 0x0100455478, count 181621, U, /usr/src/git/builtin/pack-objects.c:1702 caller 0x010045554C, count 120056, L, /usr/src/git/builtin/pack-objects.c:1834 caller 0x010045556E, count 120056, U, /usr/src/git/builtin/pack-objects.c:1837 mtx 4908/06034C8E68 lks 436, ulks 436, 324 14 95 3 0 caller 0x018014CC77, count 1, L, /oss/src/winsup/cygwin/thread.cc:475 caller 0x018014CD00, count 1, U, /oss/src/winsup/cygwin/thread.cc:496 caller 0x018014CDAF, count 432, L, /oss/src/winsup/cygwin/thread.cc:971 caller 0x018014CDE6, count 432, U, /oss/src/winsup/cygwin/thread.cc:982 caller 0x018014D07E, count 1, L, /oss/src/winsup/cygwin/thread.cc:1946 caller 0x018014D090, count 1, U, /oss/src/winsup/cygwin/thread.cc:1951 caller 0x018014D7E6, count 1, L, /oss/src/winsup/cygwin/thread.cc:525 caller 0x018014D7FF, count 1, U, /oss/src/winsup/cygwin/thread.cc:533 caller 0x018014EDD7, count 1, U, /oss/src/winsup/cygwin/thread.cc:2400 caller 0x018014EE97, count 1, L, /oss/src/winsup/cygwin/thread.cc:2389 -- Problem reports: http://cygwin.com/problems.html FAQ: http://cygwin.com/faq/ Documentation: http://cygwin.com/docs.html Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple