This is the mail archive of the libc-alpha@sourceware.org mailing list for the glibc project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

RE: [RFC][PATCH] LD_DEBUG option to measure init time


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  <m.guseva@samsung.com>

	* 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 <unistd.h>
 #include <ldsodefs.h>
 #include <exit-thread.h>
+#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 <assert.h>
 #include <string.h>
 #include <ldsodefs.h>
+#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 <stddef.h>
 #include <ldsodefs.h>
+#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 <drepper@redhat.com>, 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
+   <http://www.gnu.org/licenses/>.  */
+#include <stdio.h>
+#include <stdlib.h>
+
+__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
+# <http://www.gnu.org/licenses/>.
+
+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;
-- 
1.7.9.5



Regards,
Maria


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]