From patchwork Tue Aug 4 17:16:13 2015 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Maria Guseva X-Patchwork-Id: 8007 Received: (qmail 50585 invoked by alias); 4 Aug 2015 17:16:24 -0000 Mailing-List: contact libc-alpha-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Unsubscribe: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: libc-alpha-owner@sourceware.org Delivered-To: mailing list libc-alpha@sourceware.org Received: (qmail 50575 invoked by uid 89); 4 Aug 2015 17:16:23 -0000 Authentication-Results: sourceware.org; auth=none X-Virus-Found: No X-Spam-SWARE-Status: No, score=1.5 required=5.0 tests=AWL, BAYES_50, KAM_LAZY_DOMAIN_SECURITY, MSGID_MULTIPLE_AT, RP_MATCHES_RCVD, SPF_HELO_PASS autolearn=no version=3.3.2 X-HELO: mailout1.w1.samsung.com From: Maria Guseva To: 'Carlos O'Donell' , pinskia@gmail.com Cc: libc-alpha@sourceware.org, 'Yury Gribov' , v.garbuzov@samsung.com References: <"027601d0cac7$952818c0$bf784a40$@guseva"@samsung.com> <55BAF138.1070904@redhat.com> <6908D9A3-3615-41A8-B8BC-20CCD871AD65@gmail.com> <55BAF4C8.40200@redhat.com> <9526E1C6-ED9B-4688-A221-4DF3B8D048BA@gmail.com> <55BAF98B.2000603@redhat.com> In-reply-to: <55BAF98B.2000603@redhat.com> Subject: RE: [RFC][PATCH] LD_DEBUG option to measure init time Date: Tue, 04 Aug 2015 20:16:13 +0300 Message-id: <"039401d0ced9$44783ca0$cd68b5e0$@guseva"@samsung.com> MIME-version: 1.0 Content-type: text/plain; charset=us-ascii Content-transfer-encoding: 7bit Hi, all. Thank you for feedback. I've reworked initial patch according to it. >> I'm also thinking about having such feature for platforms without HP >> timing available, like arm. Some generic time measurements may be used >> e.g. via clock_gettime syscall. > Yes please. That would be a requirement of acceptance, it should work on all machines. I would like to add some generic timing to support platforms where HP time is unavailable. But it looks to me like separate patch which should affect other existing features like LD_DEBUG=statistics where HP_TIMING_NONAVAIL is checked as well. I think it might be some "nonhp-timing.h" header with equivalents of HP_TIMING_* macros redefined in generic approach. Thus it should entail not major changes in other glibc sources using them. With below patch the ctors/dtors timing is printed only for platforms where HP time is available as it's already works for relocation statistics for example. Tested patch on x86_64 platform. On platforms without HP time new feature isn't used at all and isn't shown in LD_DEBUG=help. 2015-08-04 Maria Guseva * csu/libc-start.c: Include hp-timing.h (LIBC_START_MAIN): Add timing and print for DL_DEBUG_CTORDTOR_TIME. * elf/Makefile (test-srcs): Add tst-ctordtor_time. (tests-special): Add tst-ctordtor_time. (tst-ctordtor_time.out): Add rule for new test. * elf/dl-fini.c: Include hp-timing.h. (_dl_fini): Add timing and print for DL_DEBUG_CTORDTOR_TIME. * elf/dl-init.c: Include hp-timing.h. (call_init): Add timing and print for DL_DEBUG_CTORDTOR_TIME. * elf/rtld.c (debopts): Changed len of struct fields name and helptext, add element for DL_DEBUG_CTORDTOR_TIME. (process_dl_debug): Fix print for new DL_DEBUG_CTORDTOR_TIME element. * elf/tst-ctordtor_time.c: New test for LD_DEBUG=ctordtor_time. * elf/tst-ctordtor_time.sh: New test for LD_DEBUG=ctordtor_time. * sysdeps/generic/ldsodefs.h (DL_DEBUG_CTORDTOR_TIME): New define. --- csu/libc-start.c | 24 +++++++++++++++++++ elf/Makefile | 8 +++++-- elf/dl-fini.c | 55 +++++++++++++++++++++++++++++++++++++++++++ elf/dl-init.c | 48 +++++++++++++++++++++++++++++++++++++ elf/rtld.c | 12 +++++++--- elf/tst-ctordtor_time.c | 41 ++++++++++++++++++++++++++++++++ elf/tst-ctordtor_time.sh | 56 ++++++++++++++++++++++++++++++++++++++++++++ sysdeps/generic/ldsodefs.h | 1 + 9 files changed, 258 insertions(+), 5 deletions(-) create mode 100644 elf/tst-ctordtor_time.c create mode 100644 elf/tst-ctordtor_time.sh diff --git a/csu/libc-start.c b/csu/libc-start.c index 138418a..faeb111 100644 --- a/csu/libc-start.c +++ b/csu/libc-start.c @@ -21,6 +21,7 @@ #include #include #include +#include "hp-timing.h" extern void __libc_init_first (int argc, char **argv, char **envp); #ifndef SHARED @@ -242,8 +243,31 @@ LIBC_START_MAIN (int (*main) (int, char **, char ** MAIN_AUXVEC_DECL), GLRO(dl_debug_printf) ("\ninitialize program: %s\n\n", argv[0]); #endif if (init) + { +#if defined SHARED && ! defined HP_TIMING_NONAVAIL + hp_timing_t init_time; + hp_timing_t start_time; + hp_timing_t end_time; + if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + HP_TIMING_NOW (start_time); +#endif + (*init) (argc, argv, __environ MAIN_AUXVEC_PARAM); +#if defined SHARED && ! defined HP_TIMING_NONAVAIL + if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + { + HP_TIMING_NOW (end_time); + HP_TIMING_DIFF (init_time, start_time, end_time); + char buf[200]; + HP_TIMING_PRINT (buf, sizeof (buf), init_time); + GLRO (dl_debug_printf) ("%s => %s: spent %s in init (== 0x%0*lx)\n", + argv[0], argv[0], buf, (int) sizeof (void *) * 2, + (unsigned long int) init); + } +#endif + + } #ifdef SHARED /* Auditing checkpoint: we have a new object. */ if (__glibc_unlikely (GLRO(dl_naudit) > 0)) diff --git a/elf/Makefile b/elf/Makefile index 25012cc..716ed4e 100644 --- a/elf/Makefile +++ b/elf/Makefile @@ -151,7 +151,7 @@ tests += loadtest restest1 preloadtest loadfail multiload origtest resolvfail \ ifeq ($(build-hardcoded-path-in-tests),yes) tests += tst-dlopen-aout endif -test-srcs = tst-pathopt +test-srcs = tst-pathopt tst-ctordtor_time selinux-enabled := $(shell cat /selinux/enforce 2> /dev/null) ifneq ($(selinux-enabled),1) tests-execstack-yes = tst-execstack tst-execstack-needed tst-execstack-prog @@ -270,7 +270,7 @@ tests-special += $(objpfx)order-cmp.out $(objpfx)tst-array1-cmp.out \ $(objpfx)tst-array5-static-cmp.out $(objpfx)order2-cmp.out \ $(objpfx)tst-initorder-cmp.out \ $(objpfx)tst-initorder2-cmp.out $(objpfx)tst-unused-dep.out \ - $(objpfx)tst-unused-dep-cmp.out + $(objpfx)tst-unused-dep-cmp.out $(objpfx)tst-ctordtor_time.out endif check-abi: $(objpfx)check-abi-ld.out @@ -1162,3 +1162,7 @@ $(objpfx)tst-unused-dep.out: $(objpfx)testobj1.so $(objpfx)tst-unused-dep-cmp.out: $(objpfx)tst-unused-dep.out cmp $< /dev/null > $@; \ $(evaluate-test) + +$(objpfx)tst-ctordtor_time.out: tst-ctordtor_time.sh $(objpfx)tst-ctordtor_time + $(SHELL) $< $(common-objpfx) '$(test-program-prefix-before-env)' \ + '$(run-program-env)' '$(test-program-prefix-after-env)' diff --git a/elf/dl-fini.c b/elf/dl-fini.c index c355775..8450cc4 100644 --- a/elf/dl-fini.c +++ b/elf/dl-fini.c @@ -20,6 +20,7 @@ #include #include #include +#include "hp-timing.h" /* Type of the constructor functions. */ @@ -142,6 +143,11 @@ _dl_fini (void) determining the order of the modules once again from the beginning. */ struct link_map **maps = NULL; size_t maps_size = 0; +#ifndef HP_TIMING_NONAVAIL + hp_timing_t fini_time; + hp_timing_t start_time; + hp_timing_t end_time; +#endif /* We run the destructors of the main namespaces last. As for the other namespaces, we pick run the destructors in them in reverse @@ -249,12 +255,61 @@ _dl_fini (void) unsigned int i = (l->l_info[DT_FINI_ARRAYSZ]->d_un.d_val / sizeof (ElfW(Addr))); while (i-- > 0) + { +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely + (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + HP_TIMING_NOW (start_time); +#endif ((fini_t) array[i]) (); +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely + (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + { + HP_TIMING_NOW (end_time); + HP_TIMING_DIFF (fini_time, start_time, + end_time); + char buf[200]; + HP_TIMING_PRINT (buf, sizeof (buf), fini_time); + _dl_debug_printf + ("%s => %s: spent %s in .fini_array[%u] (== 0x%0*lx)\n", + DSO_FILENAME (maps[0]->l_name), + DSO_FILENAME (l->l_name), buf, i, + (int) sizeof (void *) * 2, + (unsigned long int) ((fini_t) array[i] - + l->l_addr)); + } +#endif + } } /* Next try the old-style destructor. */ if (l->l_info[DT_FINI] != NULL) + { +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely + (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + HP_TIMING_NOW (start_time); +#endif DL_CALL_DT_FINI(l, l->l_addr + l->l_info[DT_FINI]->d_un.d_ptr); +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely + (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + { + HP_TIMING_NOW (end_time); + HP_TIMING_DIFF (fini_time, start_time, end_time); + char buf[200]; + HP_TIMING_PRINT (buf, sizeof (buf), fini_time); + _dl_debug_printf + ("%s => %s: spent %s in .fini (== 0x%0*lx)\n", + DSO_FILENAME (maps[0]->l_name), + DSO_FILENAME (l->l_name), buf, + (int) sizeof (void *) * 2, + (unsigned long int) (l->l_info[DT_FINI]->d_un. + d_ptr)); + } +#endif + } } #ifdef SHARED diff --git a/elf/dl-init.c b/elf/dl-init.c index 598df3b..2394b40 100644 --- a/elf/dl-init.c +++ b/elf/dl-init.c @@ -18,6 +18,7 @@ #include #include +#include "hp-timing.h" /* Type of the initializer. */ @@ -33,6 +34,11 @@ extern int _dl_starting_up_internal attribute_hidden; static void call_init (struct link_map *l, int argc, char **argv, char **env) { +#ifndef HP_TIMING_NONAVAIL + hp_timing_t init_time; + hp_timing_t start_time; + hp_timing_t end_time; +#endif if (l->l_init_called) /* This object is all done. */ return; @@ -61,7 +67,27 @@ call_init (struct link_map *l, int argc, char **argv, char **env) - the others in the DT_INIT_ARRAY. */ if (l->l_info[DT_INIT] != NULL) + { +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + HP_TIMING_NOW (start_time); +#endif DL_CALL_DT_INIT(l, l->l_addr + l->l_info[DT_INIT]->d_un.d_ptr, argc, argv, env); +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + { + HP_TIMING_NOW (end_time); + HP_TIMING_DIFF (init_time, start_time, end_time); + char buf[200]; + HP_TIMING_PRINT (buf, sizeof (buf), init_time); + _dl_debug_printf ("%s => %s: spent %s in .init (== 0x%0*lx)\n", + argv[0], DSO_FILENAME (l->l_name), buf, + (int) sizeof (void *) * 2, + (unsigned long int) (l->l_info[DT_INIT]->d_un. + d_ptr)); + } +#endif + } /* Next see whether there is an array with initialization functions. */ ElfW(Dyn) *init_array = l->l_info[DT_INIT_ARRAY]; @@ -75,7 +101,29 @@ call_init (struct link_map *l, int argc, char **argv, char **env) addrs = (ElfW(Addr) *) (init_array->d_un.d_ptr + l->l_addr); for (j = 0; j < jm; ++j) + { +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely + (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + HP_TIMING_NOW (start_time); +#endif ((init_t) addrs[j]) (argc, argv, env); +#ifndef HP_TIMING_NONAVAIL + if (__glibc_unlikely + (GLRO (dl_debug_mask) & DL_DEBUG_CTORDTOR_TIME)) + { + HP_TIMING_NOW (end_time); + HP_TIMING_DIFF (init_time, start_time, end_time); + char buf[200]; + HP_TIMING_PRINT (buf, sizeof (buf), init_time); + _dl_debug_printf + ("%s => %s: spent %s in .init_array[%u] (== 0x%0*lx)\n", + argv[0], DSO_FILENAME (l->l_name), buf, j, + (int) sizeof (void *) * 2, + (unsigned long int) (addrs[j] - l->l_addr)); + } +#endif + } } } diff --git a/elf/rtld.c b/elf/rtld.c index d5cace8..8da99cc 100644 --- a/elf/rtld.c +++ b/elf/rtld.c @@ -2213,8 +2213,8 @@ process_dl_debug (const char *dl_debug) static const struct { unsigned char len; - const char name[10]; - const char helptext[41]; + const char name[16]; + const char helptext[44]; unsigned short int mask; } debopts[] = { @@ -2241,6 +2241,12 @@ process_dl_debug (const char *dl_debug) DL_DEBUG_STATISTICS }, { LEN_AND_STR ("unused"), "determined unused DSOs", DL_DEBUG_UNUSED }, + // The "ctordtor_time" works only when HP_TIMING is available +#ifndef HP_TIMING_NONAVAIL + { LEN_AND_STR ("ctordtor_time"), + "display constructors/destructors statistics", + DL_DEBUG_CTORDTOR_TIME }, +#endif { LEN_AND_STR ("help"), "display this help message and exit", DL_DEBUG_HELP }, }; @@ -2300,7 +2306,7 @@ Valid options for the LD_DEBUG environment variable are:\n\n"); for (cnt = 0; cnt < ndebopts; ++cnt) _dl_printf (" %.*s%s%s\n", debopts[cnt].len, debopts[cnt].name, - " " + debopts[cnt].len - 3, + " " + debopts[cnt].len - 3, debopts[cnt].helptext); _dl_printf ("\n\ diff --git a/elf/tst-ctordtor_time.c b/elf/tst-ctordtor_time.c new file mode 100644 index 0000000..11888dc --- /dev/null +++ b/elf/tst-ctordtor_time.c @@ -0,0 +1,41 @@ +/* Test for LD_DEBUG=ctordtor_time option. + + Copyright (C) 2004-2014 Free Software Foundation, Inc. + This file is part of the GNU C Library. + Contributed by Ulrich Drepper , 2004. + + The GNU C Library is free software; you can redistribute it and/or + modify it under the terms of the GNU Lesser General Public + License as published by the Free Software Foundation; either + version 2.1 of the License, or (at your option) any later version. + + The GNU C Library is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU + Lesser General Public License for more details. + + You should have received a copy of the GNU Lesser General Public + License along with the GNU C Library; if not, see + . */ +#include +#include + +__attribute__ ((constructor)) + static void main_ctor_func () +{ + printf ("\nfunction main_ctor_func invoked\n"); + fflush (0); +} + +__attribute__ ((destructor)) + static void main_dtor_func () +{ + printf ("\nfunction main_dtor_func invoked\n"); + fflush (0); +} + +int +main (void) +{ + return 0; +} diff --git a/elf/tst-ctordtor_time.sh b/elf/tst-ctordtor_time.sh new file mode 100644 index 0000000..322b69b --- /dev/null +++ b/elf/tst-ctordtor_time.sh @@ -0,0 +1,56 @@ +#! /bin/sh +# Test for LD_DEBUG=ctordtor_time option. +# +# Copyright (C) 2015 Free Software Foundation, Inc. +# This file is part of the GNU C Library. + +# The GNU C Library is free software; you can redistribute it and/or +# modify it under the terms of the GNU Lesser General Public +# License as published by the Free Software Foundation; either +# version 2.1 of the License, or (at your option) any later version. + +# The GNU C Library is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +# Lesser General Public License for more details. + +# You should have received a copy of the GNU Lesser General Public +# License along with the GNU C Library; if not, see +# . + +set -o pipefail +common_objpfx=$1 +test_program_prefix_before_env=$2 +run_program_env=$3 +test_program_prefix_after_env=$4 + +TEST="tst-ctordtor_time" +CTOR_OUTPUT="function main_ctor_func invoked" +DTOR_OUTPUT="function main_dtor_func invoked" + +${test_program_prefix_before_env} ${run_program_env} LD_DEBUG=help ${test_program_prefix_after_env} ${common_objpfx}elf/$TEST >${common_objpfx}elf/$TEST.out 2>&1 +grep "ctordtor_time" ${common_objpfx}elf/$TEST.out -wq +if test $? -ne 0; then + echo "***LD_DEBUG=ctordtor_time is not supported on this platform" + exit 0 +fi + +${test_program_prefix_before_env} ${run_program_env} LD_DEBUG=ctordtor_time ${test_program_prefix_after_env} ${common_objpfx}elf/$TEST >>${common_objpfx}elf/$TEST.out 2>&1; status=$? +if test $status -ne 0; then + echo "***Failed to run ${common_objpfx}elf/$TEST" + exit $status +fi + +sed -n -e "/$CTOR_OUTPUT/,+1p" ${common_objpfx}elf/$TEST.out | sed -n '2p' | grep "[0-9]\+:\s${common_objpfx}elf/$TEST => ${common_objpfx}elf/$TEST: spent [0-9]\+ cycles in init (== 0x[0-9a-fA-F]\+)$" -q; status=$? +if test $status -ne 0; then + echo "***LD_DEBUG=ctordtor_time log for constructor is not found in output" + exit $status +fi + +sed -n -e "/$DTOR_OUTPUT/,+1p" ${common_objpfx}elf/$TEST.out | sed -n '2p' | grep "[0-9]\+:\s${common_objpfx}elf/$TEST => ${common_objpfx}elf/$TEST: spent [0-9]\+ cycles in .fini_array\[[0-9]\+\] (== 0x[0-9a-fA-F]\+)$" -q; status=$? +if test $status -ne 0; then + echo "***LD_DEBUG=ctordtor_time log for destructor is not found in output" + exit $status +fi + +exit 0 diff --git a/sysdeps/generic/ldsodefs.h b/sysdeps/generic/ldsodefs.h index e01df84..cb9c5b2 100644 --- a/sysdeps/generic/ldsodefs.h +++ b/sysdeps/generic/ldsodefs.h @@ -452,6 +452,7 @@ struct rtld_global_ro /* These two are used only internally. */ #define DL_DEBUG_HELP (1 << 10) #define DL_DEBUG_PRELINK (1 << 11) +#define DL_DEBUG_CTORDTOR_TIME (1 << 12) /* OS version. */ EXTERN unsigned int _dl_osversion;