diff mbox

[RFC] LD_DEBUG option to measure init time

Message ID "039401d0ced9$44783ca0$cd68b5e0$@guseva"@samsung.com
State New
Headers show

Commit Message

Maria Guseva Aug. 4, 2015, 5:16 p.m. UTC
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

Comments

Carlos O'Donell Aug. 4, 2015, 6:55 p.m. UTC | #1
On 08/04/2015 01:16 PM, Maria Guseva wrote:
> 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 agree that two distinct patches are a good idea. However, I want to set the
expectation that for a complete implementation you must support both. I do
not consider this a complete solution until both HP and non-HP timings
are supported, either via a generic solution for HP or another interface.

> 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.

We already have a generic hp-timing.h e.g. sysdeps/generic/hp-timing.h.
See the comments in that file. A generic solution would use gettimeofday
and provide a generic implementation. However, the overhead of gettimeofday
might be sufficient that it ruins the value of the results. I don't think
it matters, I think a generic "works everywhere" solution would be best
(helps new ports) However, that patch should be distinct, and the community
should comment on it.

> 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.

Can you please test on one non-HP platform to show it still compiles and you
didn't make any mistakes there?
 
> +#if defined SHARED && ! defined HP_TIMING_NONAVAIL

Should use `HP_TIMING_NONAVAIL', never `defined HP_TIMING_NONAVAIL' since
all macros should always be defined to a value of 0 or 1.

Likewise everywhere else.
See: https://sourceware.org/glibc/wiki/Wundef

Overall the patch is looking really good. I don't have enough time to review
thoroughly until 2.23 branches. Please ping again after the development branch
opens.

Cheers,
Carlos.
Maria Guseva Aug. 26, 2015, 12:38 p.m. UTC | #2
Hi,

In previous message the patch is displayed with unintended formatting
issues. Sending it now as an attachment.


Regards,
Maria
diff mbox

Patch

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;