Bug 198147 - [hwpmc] running pmcstat -t (top mode) whilst a process is running doesn't resolve the symbols correctly
Summary: [hwpmc] running pmcstat -t (top mode) whilst a process is running doesn't res...
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Only Me
Assignee: Stanislav Sedov
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-03-02 01:45 UTC by Adrian Chadd
Modified: 2015-06-02 08:03 UTC (History)
4 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Adrian Chadd freebsd_committer freebsd_triage 2015-03-02 01:45:00 UTC
When running hwpmc on -HEAD or -10 (and likely earlier), there's a difference between running pmcstat in top mode /before/ and /after/ the process under inspection.

If the order is:

* run pmcstat in top mode;
* start process under inspection;

Then symbol resolution looks fine.

If the order is:

* start process under inspection;
* run pmcstat in top mode;

.. then it sees events for the process, but the resolved symbols aren't always correct or working at all.
Comment 1 ganbold 2015-04-14 03:33:06 UTC
I tried to run pmcstat in top mode after starting specific program. pmcstat seems show userland symbols like:

PMC: [INSTR_RETIRED_ANY] Samples: 17452 (100.0%) , 207 unresolved

%SAMP IMAGE      FUNCTION             CALLERS
 42.4 shuultuur  scanblock
  7.3 shuultuur  runtime.MSpan_Sweep
  3.0 shuultuur  code.google.com/p/go
  2.8 shuultuur  hash/crc32.update
  2.6 shuultuur  runtime.readvarint
  2.0 shuultuur  runtime.step
  2.0 shuultuur  strings.Map
  1.4 shuultuur  runtime.findfunc
  1.4 shuultuur  runtime.stringiter2
  1.3 shuultuur  compress/flate.(*dec
  1.3 shuultuur  unicode.ToLower
  1.1 shuultuur  compress/flate.(*dec
  1.1 shuultuur  runtime.memmove
  1.1 shuultuur  runtime.mallocgc
  1.1 shuultuur  runtime.pcvalue
  0.8 shuultuur  unicode.to
  0.7 shuultuur  compress/flate.(*dec
  0.7 kernel     trash_ctor
  0.7 shuultuur  runtime.gentraceback
  0.7 shuultuur  code.google.com/p/go
  0.6 shuultuur  code.google.com/p/go
  0.6 shuultuur  bufio.(*Reader).Read
  0.6 kernel     witness_unlock
  0.5 kernel     trash_dtor
  0.5 shuultuur  main.func.001
  0.5 shuultuur  code.google.com/p/go
...

Can you show some sample ?
Comment 2 Adrian Chadd freebsd_committer freebsd_triage 2015-04-14 03:53:03 UTC
The problem isn't just that you don't see things; it's that you see /different/ things between running pmcstat before versus after the program starts.

Try nginx under load.
Comment 3 John Baldwin freebsd_committer freebsd_triage 2015-05-08 20:34:45 UTC
I definitely see this here in my same test setup as the other bug.  I've never gotten it resolve any user symbols in fact, but I've always been running pmcstat after starting the process:

PMC: [branch-instruction-retired] Samples: 351879 (100.0%) , 350556 unresolved

%SAMP IMAGE      FUNCTION             CALLERS
 50.2 kernel     _mtx_lock_spin_cooki __mtx_lock_spin_flags
  9.4 kernel     spinlock_exit        _mtx_lock_spin_cookie:5.1 ...
  5.4 hwpmc.ko   pmclog_process_callc pmc_process_samples
  5.4 kernel     __mtx_lock_spin_flag pmclog_reserve
  4.2 hwpmc.ko   pmclog_reserve       pmclog_process_callchain
  3.3 kernel     spinlock_enter       _mtx_lock_spin_cookie:1.5 ...
  3.0 hwpmc.ko   pmc_process_samples  pmc_hook_handler
  2.7 kernel     __mtx_unlock_spin_fl pmclog_release
  2.6 hwpmc.ko   soft_get_config      pmc_process_samples
  1.9 kernel     critical_exit        spinlock_exit
  1.7 kernel     atomic_subtract_barr pmc_process_samples
  1.2 hwpmc.ko   pmclog_release       pmc_process_samples
  1.1 kernel     witness_lock         pmclog_reserve
  0.6 kernel     witness_unlock       __mtx_unlock_spin_flags
  0.6 kernel     critical_enter
  0.6 kernel     cpu_search_lowest
  0.5 kernel     witness_checkorder
  0.5 hwpmc.ko   iap_get_config

(Nothing from threadspin, and it was built with -g)

If I run threadspin directly instead of using -t `pgrep threadspin`, then it works:

PMC: [branch-instruction-retired] Samples: 162009 (100.0%) , 0 unresolved

%SAMP IMAGE      FUNCTION             CALLERS
 99.7 threadspin worker               0x8744
Comment 4 Stanislav Sedov freebsd_committer freebsd_triage 2015-05-12 04:35:56 UTC
I believe I did figure out the cause of the problem.  Pmcstat fails to correctly determine the virtual address of the text segment when multiple sections are present.  It does not make a difference when pmcstat sees exec event, but causes it to fail when examining already running processes.  I will post a patch to the fabricator shortly.
Comment 5 commit-hook freebsd_committer freebsd_triage 2015-05-13 18:53:01 UTC
A commit references this bug:

Author: stas
Date: Wed May 13 18:52:18 UTC 2015
New revision: 282866
URL: https://svnweb.freebsd.org/changeset/base/282866

Log:
  Fix pmcstat symbol resolution for userland processes.

  When examining existing processes pmcstat fails to
  correctly determine the locations of executable sections
  of the process due to a miscalculated virtual load address.
  This does not affect the newly launched processes as the
  same value passed as a "start address" to the pmcstat_image_link()
  thus nullifying the effect of it.  The issue manifests itself
  in processes not being reported in the pmcstat(8) output and
  "dubious frames" being reported.

  Fix it for now by ignoring all the sections except the executable
  one.  This won't fix the issue for objects with multiple
  executable sections but helps in majority of real world usecases.
  The real solution would be to modify the MAP-IN event to include
  the appropriate load address so pmcstat(8) won't have to manually
  parse object files to try to determine it.

  PR:		198147, 198148
  Reviewed by:	jhb, rpaulo
  MFC after:	2 weeks

Changes:
  head/usr.sbin/pmcstat/pmcstat_log.c
Comment 6 Stanislav Sedov freebsd_committer freebsd_triage 2015-05-13 21:54:45 UTC
This should be fixed now.
Comment 7 commit-hook freebsd_committer freebsd_triage 2015-06-02 08:03:44 UTC
A commit references this bug:

Author: hiren
Date: Tue Jun  2 08:03:29 UTC 2015
New revision: 283905
URL: https://svnweb.freebsd.org/changeset/base/283905

Log:
  MFC: r282866

  Fix pmcstat symbol resolution for userland processes.

  When examining existing processes pmcstat fails to
  correctly determine the locations of executable sections
  of the process due to a miscalculated virtual load address.
  This does not affect the newly launched processes as the
  same value passed as a "start address" to the pmcstat_image_link()
  thus nullifying the effect of it.  The issue manifests itself
  in processes not being reported in the pmcstat(8) output and
  "dubious frames" being reported.

  Fix it for now by ignoring all the sections except the executable
  one.  This won't fix the issue for objects with multiple
  executable sections but helps in majority of real world usecases.
  The real solution would be to modify the MAP-IN event to include
  the appropriate load address so pmcstat(8) won't have to manually
  parse object files to try to determine it.

  PR:		198147, 198148
  Submitted by:	stas

Changes:
_U  stable/10/
  stable/10/usr.sbin/pmcstat/pmcstat_log.c