From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from cluster-e.mailcontrol.com (cluster-e.mailcontrol.com [85.115.58.190]) by sourceware.org (Postfix) with ESMTPS id 794A9385AC20 for ; Thu, 29 Jul 2021 07:26:18 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org 794A9385AC20 Authentication-Results: sourceware.org; dmarc=none (p=none dis=none) header.from=EMEA.NEC.COM Authentication-Results: sourceware.org; spf=pass smtp.mailfrom=EMEA.NEC.COM Received: from mail1.neceur.com (mail1.neceur.com [195.47.207.3]) by rly60e.srv.mailcontrol.com (MailControl) with ESMTPS id 16T7QFIl015422 (version=TLSv1.2 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NO) for ; Thu, 29 Jul 2021 08:26:15 +0100 Received: from intmail1.neceur.com (intmail1.neceur.com [172.29.14.11]) by mail1.neceur.com (8.15.2/8.15.2/SUSE Linux 0.8) with ESMTP id 16T7QF1V028267 for ; Thu, 29 Jul 2021 08:26:15 +0100 Received: from av2.neceur.com (av2.neceur.com [172.29.177.7]) by intmail1.neceur.com (8.14.7/8.14.7) with ESMTP id 16T7QFWW006803 for ; Thu, 29 Jul 2021 08:26:15 +0100 Received: from av2.neceur.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 6632ACA051 for ; Thu, 29 Jul 2021 08:26:15 +0100 (BST) Received: from av2.neceur.com (unknown [127.0.0.1]) by IMSVA (Postfix) with ESMTP id 3E296CA050 for ; Thu, 29 Jul 2021 08:26:15 +0100 (BST) Received: from EUX13SRV1.EU.NEC.COM (unknown [172.29.155.138]) by av2.neceur.com (Postfix) with ESMTPS for ; Thu, 29 Jul 2021 08:26:15 +0100 (BST) Received: from EUX13SRV2.EU.NEC.COM (172.29.155.139) by EUX13SRV1.EU.NEC.COM (172.29.155.138) with Microsoft SMTP Server (TLS) id 15.0.1497.2; Thu, 29 Jul 2021 08:26:14 +0100 Received: from EUX13SRV2.EU.NEC.COM ([172.29.155.139]) by EUX13SRV2.EU.NEC.COM ([172.29.155.139]) with mapi id 15.00.1497.015; Thu, 29 Jul 2021 08:26:14 +0100 From: Christian Weiss To: "libc-help@sourceware.org" CC: Felix Uhl Subject: Runtime discrepancy clock_gettime + funcition instrumentation Thread-Topic: Runtime discrepancy clock_gettime + funcition instrumentation Thread-Index: AdeER+88iVjHeyDJSciWrhGLYZ+sTQ== Date: Thu, 29 Jul 2021 07:26:14 +0000 Message-ID: <5175db58f09c413b9c652d5dc45a2248@EUX13SRV2.EU.NEC.COM> Accept-Language: de-DE, en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-ms-exchange-transport-fromentityheader: Hosted x-originating-ip: [172.29.208.56] MIME-Version: 1.0 X-TM-AS-GCONF: 00 X-TM-AS-Product-Ver: IMSVA-9.1.0.1600-8.1.0.1054-22232.006 X-TMASE-Version: IMSVA-9.1.0.1600-8.1.1054-22232.006 X-TMASE-Result: 10--10.845700-10.000000 X-TMASE-MatchedRID: XD0oD+4ahO1+fF8y5Vr34lVN8laWo90MpfVcx39Kq+7McZL/toKwUnMS vPRTWdjYOBVmBYbM4YZLtYw1SZkQILQ8r94DTp63RlqShqb35p5zd7C7BtJobvHFoBcOsKezDYJ QbNnE3Z0hsoXvnmAn1GyS+Hq5x7GsdFfAwKZRe8GRsyIQ4jFl6/QhZRRMg92EVzOmd/bB9b4bmc ymLs2Q/GINlOGYJobx18LDvZDQ/Idw08wUkhf6c0KcYi5Qw/RVwLlnHU0okA2rTRU2ZmTM1jZYK 6SBwsTwO13GopiXCjwKhS6VzbaGYjyy2aRcFzEB71Wx2uUbPLdDr8MVm6DK3TA4N9SXuYkpjNLx rcxKViWMkVsdMJZ1Bn+lsrTmsmXb1lfDCm9+EZVYKMMlFh4BnYfsPVs/8Vw6EfKzCAntKpDzMbP rnKd2TMkuGv8NfTLvo7MuCMmELwiBkjWfpo1TNt/wYmMFcJSIl2F9+KxZd8cdI0m0WP5vemSPUs QNTyushFc9YFa1dsaKQiuuGSHzH5cqz3g0A4fyemu6h6JZhrmZEoWHC6Rh/QS/lfZQ9/PRP7gDL iEt/1fvsEhC8rfeWv7lKeC/Kdybmvyr8NorYSqeAiCmPx4NwGmRqNBHmBvenFK7VE/xL0m1VfZr X9mxWH8vf7+JH9WSupyykxXwhXAZtj9P8amv8S9pJrg2iiC0wMEtYIEVysEJgLHXTkRuSyrYn6Z lpGMgxb0zbB8qRMHT5SoAqscezA== X-TMASE-SNAP-Result: 1.811037.0001-0-1-12:0,22:0,34:0,39:0-0 X-MailControl-OutInfo: MTYyNzU0MzU3NjpGUEtleTEucHJpdjoXpbVmPpsonsAaPNhlowUDvhtCn2rtmrkWr5p5JORZyyzsN4yDZ3hnIkriUl2iRf5X8cFbRG5N1/ZTWXTgpvVpuWpknL3/uymK9EpviDQHy23vd5nR+F7JWVEPV0cVgFOASAvFofe0cc8iGvw+f1VtGCD8JGW6iUoF4ZKEOixNE27C2bpDaahsXF1zAJBz5TTp8xc/D9pB5BiaZZIK0SpJNtE//BeoaUJTCkbBqHjIdLq2uEpH2bM3J5LePOlcmErG5Tdh9LtF1JLdHUQzcFeIHGEOfTIdpGre2VLrsX03jhb9tYYFRVY4MznM/exsDJrVtp3eVPxw3Y3PXpdaHKQc X-Scanned-By: MailControl 44278.2116 (www.mailcontrol.com) on 10.69.0.170 X-Spam-Status: No, score=-2.6 required=5.0 tests=BAYES_00, HTML_MESSAGE, KAM_DMARC_STATUS, RCVD_IN_DNSWL_LOW, RCVD_IN_MSPIKE_H3, RCVD_IN_MSPIKE_WL, SPF_HELO_PASS, SPF_PASS, TXREP autolearn=ham autolearn_force=no version=3.4.4 X-Spam-Checker-Version: SpamAssassin 3.4.4 (2020-01-24) on server2.sourceware.org Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable X-Content-Filtered-By: Mailman/MimeDel 2.1.29 X-BeenThere: libc-help@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Libc-help mailing list List-Unsubscribe: , List-Archive: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 29 Jul 2021 07:26:22 -0000 Dear all, I made the following observation which I cannot explain. Maybe you can help= me out? I create a library which contains __cyg_profile_func_enter/exit hooks for f= unction instrumentation. I link this library to program which calls a dumm= y function a large number of times and measure the execution time. The resu= lting runtime differs significantly depending on whether I use the "-static= " flag or not. In detail: Libtime.c: #include void __cyg_profile_func_enter (void *func, void *caller) { struct timespec local_time; clock_gettime(CLOCK_MONOTONIC, &local_time); } void __cyg_profile_func_exit (void *func, void *caller) { struct timespec local_time; clock_gettime(CLOCK_MONOTONIC, &local_time); } Building a static and a shared library: gcc -c libtime.c -o libtime.o ar rcs libtime_gcc.a libtime.o gcc -c -fPIC libtime.c -o libtime.o gcc -shared -o libtime_gcc.so libtime.o The test code test.c: #include #include #define N_ITER_DEFAULT 1000 long long func_1 (long long x) { return x; } int main (int argc, char *argv[]) { long long n_iter =3D argc > 1 ? atol (argv[1]) : N_ITER_DEFAULT; long long sum =3D 0; for (long long i =3D 0; i < n_iter; i++) { sum +=3D func_1(i); } printf ("sum: %lld\n", sum); } Building: gcc -std=3Dgnu99 -finstrument-functions -static test.c -o test_time_static_= gcc.x -L. -ltime_gcc gcc -std=3Dgnu99 -finstrument-functions test.c -o test_time_dyn_gcc.x -L. -= ltime_gcc I made sure that the correct library is loaded to the dynamic binary at run= time: [cweiss@amd022 overhead]$ ldd test_time_dyn_gcc.x | grep libtime libtime_gcc.so =3D> /home/cweiss/Vftrace_examples/overhead/libtime_gc= c.so (0x00007fad0d42a000) Measuring the runtime, the static binary takes about five times more time t= o finish than the dynamic one. I do not yet understand this observation: [cweiss@amd022 overhead]$ time ./test_time_static_gcc.x 10000000 sum: 49999995000000 real 0m2.594s user 0m0.396s sys 0m2.197s [cweiss@amd022 overhead]$ time ./test_time_dyn_gcc.x 10000000 sum: 49999995000000 real 0m0.518s user 0m0.515s sys 0m0.002s Further remarks: - Libc version: 2.17 - Gcc version: 8.20. - OS: CentOS 7.8 - The issue does not appear when libtime is included explicitly an= d the "-static" flag is not used. This makes sense because then libc is lin= ked dynamically. - A perf profile shows that the number of failed branch prediction= s is significantly higher in the static version (20 million (13.34%) vs 400= 0 (0%)), Best regards, Christian Weiss Dr. Christian Weiss Benchmark Analyst Tel: +49 211 5369 126 NEC Deutschland GmbH Gesch=E4ftsf=FChrer Yuichi Kojima Handelsregister D=FCsseldorf HRB 57941; VAT ID DE129424743