[BUG] perf report/annotate: consuming too many file descriptors

[BUG] perf report/annotate: consuming too many file descriptors

[Stephane Eranian]

Hi,


I was testing 3.14-rc2 (tip.git) perf and ran into a serious problem
with report/annotate on a collection with lots of shared libraries (500).

Perf ran out of file descriptors (ulimit set to 1024). It did not print
an error message, but simply refused to proceed to objdump.

I ran strace and discovered it was running out of descriptors to
my big surprise! I narrowed it down with strace -etrace=open.
I saw an appalling result.

My .so files were opened at least 4 times each, each
allocated an fd that was kept open, each open incur a read of the ELF
headers. So each dso was consuming 4 fd.

Why?

Because of what's going on in dso__load() when perf iterates
over the binary_type_symtab[]. It tries a bunch of types. For
each match, symsrc_init() is invoked to read the ELF image.
The fd opened there is kept open (for later loading).

The first problem is why is dso__read_binary_type_filename()
blindly returning success on many types. For my files, I got matches
on DEBUGLINK, SYSTEM_DSO_PATH, GUEST_KMODULE,
SYSTEM_PATH_KMODULE.

I have a tendency to believe that the dso__read_binary_type_filename()
meaning has been abused to stash things that do not really
belong there.

Furthermore, I believe many of the type matches do NOT need an ELF
read and certainly not one that keeps a descriptor opened.

This problem is not just about consuming too many fd, it is also about
execution overhead. Why read the ELF headers 4 times?

The current situation makes reporting on large collection impossible for
regular users. I don't quite know how to best address this issue. One way
I found would be for  dso__read_binary_type_filename() to return a value
meaning success but no ELF read. Not sure would be correct, though.

Any ideas on how to fix this?

Thanks.

Re: [BUG] perf report/annotate: consuming too many file descriptors

[Namhyung Kim]

[-- Attachment #1: Type: text/plain, Size: 2230 bytes --]

Hi Stephane,

(I'd be better if you use my korg address).

2014-02-12 PM 11:32, Stephane Eranian wrote:
> Hi,
>
>
> I was testing 3.14-rc2 (tip.git) perf and ran into a serious problem
> with report/annotate on a collection with lots of shared libraries (500).
>
> Perf ran out of file descriptors (ulimit set to 1024). It did not print
> an error message, but simply refused to proceed to objdump.
>
> I ran strace and discovered it was running out of descriptors to
> my big surprise! I narrowed it down with strace -etrace=open.
> I saw an appalling result.
>
> My .so files were opened at least 4 times each, each
> allocated an fd that was kept open, each open incur a read of the ELF
> headers. So each dso was consuming 4 fd.
>
> Why?
>
> Because of what's going on in dso__load() when perf iterates
> over the binary_type_symtab[]. It tries a bunch of types. For
> each match, symsrc_init() is invoked to read the ELF image.
> The fd opened there is kept open (for later loading).
>
> The first problem is why is dso__read_binary_type_filename()
> blindly returning success on many types. For my files, I got matches
> on DEBUGLINK, SYSTEM_DSO_PATH, GUEST_KMODULE,
> SYSTEM_PATH_KMODULE.
>
> I have a tendency to believe that the dso__read_binary_type_filename()
> meaning has been abused to stash things that do not really
> belong there.
>
> Furthermore, I believe many of the type matches do NOT need an ELF
> read and certainly not one that keeps a descriptor opened.
>
> This problem is not just about consuming too many fd, it is also about
> execution overhead. Why read the ELF headers 4 times?
>
> The current situation makes reporting on large collection impossible for
> regular users. I don't quite know how to best address this issue. One way
> I found would be for  dso__read_binary_type_filename() to return a value
> meaning success but no ELF read. Not sure would be correct, though.

It looks like a case of stripped binary or static build.  dso__load() 
looked for both of symtab and dynsym, but it failed.  So it iterated 
through the binary types and continued to fail with fd open. :(

I think we should close/destroy the duplicate symsrcs.  Does attached 
patch fix your problem?

Thanks,
Namhyung


[-- Attachment #2: destory-unnecessary-symsrc.patch --]
[-- Type: text/plain, Size: 354 bytes --]

diff --git a/tools/perf/util/symbol.c b/tools/perf/util/symbol.c
index abebc2591960..cd970106de99 100644
--- a/tools/perf/util/symbol.c
+++ b/tools/perf/util/symbol.c
@@ -1337,6 +1337,8 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
 
 			if (syms_ss && runtime_ss)
 				break;
+		} else {
+			symsrc__destroy(ss);
 		}
 
 	}

Re: [BUG] perf report/annotate: consuming too many file descriptors

[Stephane Eranian]

Hi,

Your patch does solve the file consumption problem on my test case.
We still open and do the ELF read 5 times.

Now, if on top of your patch, we also add the following, we save one
open().

diff --git a/tools/perf/util/dso.c b/tools/perf/util/dso.c
index 4045d08..87a0ecb 100644
--- a/tools/perf/util/dso.c
+++ b/tools/perf/util/dso.c
@@ -45,7 +45,7 @@ int dso__read_binary_type_filename(const struct dso *dso,
  debuglink--;
  if (*debuglink == '/')
  debuglink++;
- filename__read_debuglink(dso->long_name, debuglink,
+ ret = filename__read_debuglink(dso->long_name, debuglink,
  size - (debuglink - filename));
  }
  break;

On Thu, Feb 13, 2014 at 1:33 AM, Namhyung Kim <namhyung.kim@lge.com> wrote:
> Hi Stephane,
>
> (I'd be better if you use my korg address).
>
>
> 2014-02-12 PM 11:32, Stephane Eranian wrote:
>>
>> Hi,
>>
>>
>> I was testing 3.14-rc2 (tip.git) perf and ran into a serious problem
>> with report/annotate on a collection with lots of shared libraries (500).
>>
>> Perf ran out of file descriptors (ulimit set to 1024). It did not print
>> an error message, but simply refused to proceed to objdump.
>>
>> I ran strace and discovered it was running out of descriptors to
>> my big surprise! I narrowed it down with strace -etrace=open.
>> I saw an appalling result.
>>
>> My .so files were opened at least 4 times each, each
>> allocated an fd that was kept open, each open incur a read of the ELF
>> headers. So each dso was consuming 4 fd.
>>
>> Why?
>>
>> Because of what's going on in dso__load() when perf iterates
>> over the binary_type_symtab[]. It tries a bunch of types. For
>> each match, symsrc_init() is invoked to read the ELF image.
>> The fd opened there is kept open (for later loading).
>>
>> The first problem is why is dso__read_binary_type_filename()
>> blindly returning success on many types. For my files, I got matches
>> on DEBUGLINK, SYSTEM_DSO_PATH, GUEST_KMODULE,
>> SYSTEM_PATH_KMODULE.
>>
>> I have a tendency to believe that the dso__read_binary_type_filename()
>> meaning has been abused to stash things that do not really
>> belong there.
>>
>> Furthermore, I believe many of the type matches do NOT need an ELF
>> read and certainly not one that keeps a descriptor opened.
>>
>> This problem is not just about consuming too many fd, it is also about
>> execution overhead. Why read the ELF headers 4 times?
>>
>> The current situation makes reporting on large collection impossible for
>> regular users. I don't quite know how to best address this issue. One way
>> I found would be for  dso__read_binary_type_filename() to return a value
>> meaning success but no ELF read. Not sure would be correct, though.
>
>
> It looks like a case of stripped binary or static build.  dso__load() looked
> for both of symtab and dynsym, but it failed.  So it iterated through the
> binary types and continued to fail with fd open. :(
>
> I think we should close/destroy the duplicate symsrcs.  Does attached patch
> fix your problem?
>
> Thanks,
> Namhyung
>

Re: [BUG] perf report/annotate: consuming too many file descriptors

[Namhyung Kim]

Hi Stephane,

On Thu, 13 Feb 2014 17:26:30 +0100, Stephane Eranian wrote:
> Hi,
>
> Your patch does solve the file consumption problem on my test case.
> We still open and do the ELF read 5 times.

Cool.  Could you also confirm what's the problem case - whether it's
stripped or static linked?

>
> Now, if on top of your patch, we also add the following, we save one
> open().

I think you need one more patch below on top of yours since the
filename__read_debuglink() always return -1.

Thanks,
Namhyung


diff --git a/tools/perf/util/symbol-elf.c b/tools/perf/util/symbol-elf.c
index 3e9f336740fa..8ac4a4fe2abd 100644
--- a/tools/perf/util/symbol-elf.c
+++ b/tools/perf/util/symbol-elf.c
@@ -506,6 +506,8 @@ int filename__read_debuglink(const char *filename, char *debuglink,
 	/* the start of this section is a zero-terminated string */
 	strncpy(debuglink, data->d_buf, size);
 
+	err = 0;
+
 out_elf_end:
 	elf_end(elf);
 out_close:

Re: [BUG] perf report/annotate: consuming too many file descriptors

[Namhyung Kim]

Hi Stephane,

On Thu, 13 Feb 2014 17:26:30 +0100, Stephane Eranian wrote:
> Hi,
>
> Your patch does solve the file consumption problem on my test case.
> We still open and do the ELF read 5 times.
>>> The first problem is why is dso__read_binary_type_filename()
>>> blindly returning success on many types. For my files, I got matches
>>> on DEBUGLINK, SYSTEM_DSO_PATH, GUEST_KMODULE,
>>> SYSTEM_PATH_KMODULE.

Hmm.. the dso__read_binary_type_filename() will be called for either of
user binaries or kernel modules.  But for each binary, it's pointless to
check both types of symtab since it can only have one type.

So I think we should try SYMTEM_PATH_DSO, DEBUGLINK, BUILD_ID_CACHE and
a couple of DEBUGINFOs for user binaries, and only try *_KMODULE for
kernel modules.  This way, we can reduce the unnecessary open and ELF
reading/parsing time.

Could you please test following patch also?


diff --git a/tools/perf/util/symbol.c b/tools/perf/util/symbol.c
index a9d758a3b371..303b8dc59dd8 100644
--- a/tools/perf/util/symbol.c
+++ b/tools/perf/util/symbol.c
@@ -1251,6 +1251,46 @@ out_failure:
 	return -1;
 }
 
+static bool dso__is_compatible_symtab_type(struct dso *dso, bool kmod,
+					   enum dso_binary_type type)
+{
+	switch (type) {
+	case DSO_BINARY_TYPE__JAVA_JIT:
+	case DSO_BINARY_TYPE__DEBUGLINK:
+	case DSO_BINARY_TYPE__SYSTEM_PATH_DSO:
+	case DSO_BINARY_TYPE__FEDORA_DEBUGINFO:
+	case DSO_BINARY_TYPE__UBUNTU_DEBUGINFO:
+	case DSO_BINARY_TYPE__BUILDID_DEBUGINFO:
+	case DSO_BINARY_TYPE__OPENEMBEDDED_DEBUGINFO:
+		return !kmod && dso->kernel == DSO_TYPE_USER;
+
+	case DSO_BINARY_TYPE__KALLSYMS:
+	case DSO_BINARY_TYPE__VMLINUX:
+	case DSO_BINARY_TYPE__KCORE:
+		return dso->kernel == DSO_TYPE_KERNEL;
+
+	case DSO_BINARY_TYPE__GUEST_KALLSYMS:
+	case DSO_BINARY_TYPE__GUEST_VMLINUX:
+	case DSO_BINARY_TYPE__GUEST_KCORE:
+		return dso->kernel == DSO_TYPE_GUEST_KERNEL;
+
+	case DSO_BINARY_TYPE__GUEST_KMODULE:
+	case DSO_BINARY_TYPE__SYSTEM_PATH_KMODULE:
+		/*
+		 * kernel modules know their symtab type - it's set when
+		 * creating a module dso in machine__new_module().
+		 */
+		return kmod && dso->symtab_type == type;
+
+	case DSO_BINARY_TYPE__BUILD_ID_CACHE:
+		return true;
+
+	case DSO_BINARY_TYPE__NOT_FOUND:
+	default:
+		return false;
+	}
+}
+
 int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
 {
 	char *name;
@@ -1261,6 +1301,7 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
 	int ss_pos = 0;
 	struct symsrc ss_[2];
 	struct symsrc *syms_ss = NULL, *runtime_ss = NULL;
+	bool kmod;
 
 	dso__set_loaded(dso, map->type);
 
@@ -1301,7 +1342,11 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
 	if (!name)
 		return -1;
 
-	/* Iterate over candidate debug images.
+	kmod = dso->symtab_type == DSO_BINARY_TYPE__SYSTEM_PATH_KMODULE ||
+		dso->symtab_type == DSO_BINARY_TYPE__GUEST_KMODULE;
+
+	/*
+	 * Iterate over candidate debug images.
 	 * Keep track of "interesting" ones (those which have a symtab, dynsym,
 	 * and/or opd section) for processing.
 	 */
@@ -1311,6 +1356,9 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
 
 		enum dso_binary_type symtab_type = binary_type_symtab[i];
 
+		if (!dso__is_compatible_symtab_type(dso, kmod, symtab_type))
+			continue;
+
 		if (dso__read_binary_type_filename(dso, symtab_type,
 						   root_dir, name, PATH_MAX))
 			continue;
@@ -1351,15 +1399,10 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
 	if (!runtime_ss && syms_ss)
 		runtime_ss = syms_ss;
 
-	if (syms_ss) {
-		int km;
-
-		km = dso->symtab_type == DSO_BINARY_TYPE__SYSTEM_PATH_KMODULE ||
-		     dso->symtab_type == DSO_BINARY_TYPE__GUEST_KMODULE;
-		ret = dso__load_sym(dso, map, syms_ss, runtime_ss, filter, km);
-	} else {
+	if (syms_ss)
+		ret = dso__load_sym(dso, map, syms_ss, runtime_ss, filter, kmod);
+	else
 		ret = -1;
-	}
 
 	if (ret > 0) {
 		int nr_plt;

Re: [BUG] perf report/annotate: consuming too many file descriptors

[Stephane Eranian]

Hi,


On Fri, Feb 14, 2014 at 8:11 AM, Namhyung Kim <namhyung@kernel.org> wrote:
>
> Hi Stephane,
>
> On Thu, 13 Feb 2014 17:26:30 +0100, Stephane Eranian wrote:
> > Hi,
> >
> > Your patch does solve the file consumption problem on my test case.
> > We still open and do the ELF read 5 times.
> >>> The first problem is why is dso__read_binary_type_filename()
> >>> blindly returning success on many types. For my files, I got matches
> >>> on DEBUGLINK, SYSTEM_DSO_PATH, GUEST_KMODULE,
> >>> SYSTEM_PATH_KMODULE.
>
> Hmm.. the dso__read_binary_type_filename() will be called for either of
> user binaries or kernel modules.  But for each binary, it's pointless to
> check both types of symtab since it can only have one type.
>
> So I think we should try SYMTEM_PATH_DSO, DEBUGLINK, BUILD_ID_CACHE and
> a couple of DEBUGINFOs for user binaries, and only try *_KMODULE for
> kernel modules.  This way, we can reduce the unnecessary open and ELF
> reading/parsing time.
>
> Could you please test following patch also?
>
Patch worked on my test case.
Thanks.


>
>
> diff --git a/tools/perf/util/symbol.c b/tools/perf/util/symbol.c
> index a9d758a3b371..303b8dc59dd8 100644
> --- a/tools/perf/util/symbol.c
> +++ b/tools/perf/util/symbol.c
> @@ -1251,6 +1251,46 @@ out_failure:
>         return -1;
>  }
>
> +static bool dso__is_compatible_symtab_type(struct dso *dso, bool kmod,
> +                                          enum dso_binary_type type)
> +{
> +       switch (type) {
> +       case DSO_BINARY_TYPE__JAVA_JIT:
> +       case DSO_BINARY_TYPE__DEBUGLINK:
> +       case DSO_BINARY_TYPE__SYSTEM_PATH_DSO:
> +       case DSO_BINARY_TYPE__FEDORA_DEBUGINFO:
> +       case DSO_BINARY_TYPE__UBUNTU_DEBUGINFO:
> +       case DSO_BINARY_TYPE__BUILDID_DEBUGINFO:
> +       case DSO_BINARY_TYPE__OPENEMBEDDED_DEBUGINFO:
> +               return !kmod && dso->kernel == DSO_TYPE_USER;
> +
> +       case DSO_BINARY_TYPE__KALLSYMS:
> +       case DSO_BINARY_TYPE__VMLINUX:
> +       case DSO_BINARY_TYPE__KCORE:
> +               return dso->kernel == DSO_TYPE_KERNEL;
> +
> +       case DSO_BINARY_TYPE__GUEST_KALLSYMS:
> +       case DSO_BINARY_TYPE__GUEST_VMLINUX:
> +       case DSO_BINARY_TYPE__GUEST_KCORE:
> +               return dso->kernel == DSO_TYPE_GUEST_KERNEL;
> +
> +       case DSO_BINARY_TYPE__GUEST_KMODULE:
> +       case DSO_BINARY_TYPE__SYSTEM_PATH_KMODULE:
> +               /*
> +                * kernel modules know their symtab type - it's set when
> +                * creating a module dso in machine__new_module().
> +                */
> +               return kmod && dso->symtab_type == type;
> +
> +       case DSO_BINARY_TYPE__BUILD_ID_CACHE:
> +               return true;
> +
> +       case DSO_BINARY_TYPE__NOT_FOUND:
> +       default:
> +               return false;
> +       }
> +}
> +
>  int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
>  {
>         char *name;
> @@ -1261,6 +1301,7 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
>         int ss_pos = 0;
>         struct symsrc ss_[2];
>         struct symsrc *syms_ss = NULL, *runtime_ss = NULL;
> +       bool kmod;
>
>         dso__set_loaded(dso, map->type);
>
> @@ -1301,7 +1342,11 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
>         if (!name)
>                 return -1;
>
> -       /* Iterate over candidate debug images.
> +       kmod = dso->symtab_type == DSO_BINARY_TYPE__SYSTEM_PATH_KMODULE ||
> +               dso->symtab_type == DSO_BINARY_TYPE__GUEST_KMODULE;
> +
> +       /*
> +        * Iterate over candidate debug images.
>          * Keep track of "interesting" ones (those which have a symtab, dynsym,
>          * and/or opd section) for processing.
>          */
> @@ -1311,6 +1356,9 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
>
>                 enum dso_binary_type symtab_type = binary_type_symtab[i];
>
> +               if (!dso__is_compatible_symtab_type(dso, kmod, symtab_type))
> +                       continue;
> +
>                 if (dso__read_binary_type_filename(dso, symtab_type,
>                                                    root_dir, name, PATH_MAX))
>                         continue;
> @@ -1351,15 +1399,10 @@ int dso__load(struct dso *dso, struct map *map, symbol_filter_t filter)
>         if (!runtime_ss && syms_ss)
>                 runtime_ss = syms_ss;
>
> -       if (syms_ss) {
> -               int km;
> -
> -               km = dso->symtab_type == DSO_BINARY_TYPE__SYSTEM_PATH_KMODULE ||
> -                    dso->symtab_type == DSO_BINARY_TYPE__GUEST_KMODULE;
> -               ret = dso__load_sym(dso, map, syms_ss, runtime_ss, filter, km);
> -       } else {
> +       if (syms_ss)
> +               ret = dso__load_sym(dso, map, syms_ss, runtime_ss, filter, kmod);
> +       else
>                 ret = -1;
> -       }
>
>         if (ret > 0) {
>                 int nr_plt;