pmcstat -G doesn't seem to resolve symbols from userland processes correctly or reliably. In almost every instance, running pmcstat -G on a log file just plainly doesn't resolve anything that isn't a kernel symbol. To reproduce: * run some very CPU busy process with lots of threads and syscalls; * run pmcstat -O to record events to a logfile; * when you're done, try using pmcstat -R <file> -G to spit out the callgraph to stdout. Even if all of the events are process-spec, I see /just/ kernel events. This happens on both -HEAD and -10.
On -HEAD (r278050M), I do see non-kernel events. # pmcstat -S instructions -O /var/tmp/sample # pmcstat -R /var/tmp/sample -G /var/tmp/sample.callgraph In sample.callgraph, I see things like 00.24% [1] sqlite3_column_bytes @ /usr/local/lib/libsqlite3.so.0.8.6 100.0% [1] 0xdb799d @ /usr/local/lib/firefox/libxul.so 00.24% [1] unixShmLock @ /usr/local/lib/libsqlite3.so.0.8.6 100.0% [1] walTryBeginRead 100.0% [1] sqlite3PagerSharedLock 100.0% [1] sqlite3BtreeBeginTrans 100.0% [1] sqlite3VdbeExec 100.0% [1] sqlite3_step 100.0% [1] 0xdb06b1 @ /usr/local/lib/firefox/libxul.so 00.24% [1] copy_boxes @ /usr/local/lib/libcairo.so.2.11200.18 100.0% [1] clip_and_composite_boxes 100.0% [1] _cairo_traps_compositor_paint 100.0% [1] _cairo_compositor_paint 100.0% [1] _cairo_surface_paint 100.0% [1] _cairo_gstate_paint 100.0% [1] _cairo_default_context_paint_with_alpha 100.0% [1] cairo_paint_with_alpha 100.0% [1] 0xf540c6 @ /usr/local/lib/firefox/libxul.so Am I understanding this correctly?
Yeah. Try running something that you know is pegging CPUs in a tight loop of doing work (like a busy webserveR) and where the processes aren't being created / destroyed. I don't see any events; i only see the kernel ones. You're seeing '1' event, which isn't exactly a lot. What were you doing?
I'm running some content filtering software written in Go and did some load on it. I tried pmcstat. As Hiren, I see userland symbols in callgraph like: ... 50.69% [359402] scanblock @ /usr/home/tsgan/go/bin/shuultuur 00.04% [140] net.(*netFD).decref 00.01% [23] os.Lstat 00.00% [13] runtime.netpollinit 00.00% [10] runtime.goexit -- 08.61% [61068] runtime.MSpan_Sweep @ /usr/home/tsgan/go/bin/shuultuur 02.33% [16554] hash/crc32.update @ /usr/home/tsgan/go/bin/shuultuur 00.03% [5] hash/crc32.Update 00.01% [1] reflect.cvtFloatInt 00.01% [1] net/textproto.(*dotReader).Read 00.01% [1] reflect.(*rtype).Implements -- 01.34% [9528] compress/flate.(*decompressor).huffSym @ /usr/home/tsgan/go/bin/shuultuur 01.20% [8515] runtime.readvarint @ /usr/home/tsgan/go/bin/shuultuur 01.43% [122] runtime.step 00.05% [4] runtime.goparkunlock 00.01% [1] net/http.(*persistConn).wroteRequest 00.01% [1] net/http.(*persistConn).markBroken -- 01.10% [7832] code.google.com/p/go.net/html.(*Tokenizer).readByte @ /usr/home/tsgan/go/bin/shuultuur 00.63% [49] code.google.com/p/go.net/html.(*Tokenizer).Next 00.31% [24] code.google.com/p/go.net/html.(*Tokenizer).readScript 00.27% [21] code.google.com/p/go.net/html.(*Tokenizer).readTagAttrVal 00.09% [7] code.google.com/p/go.net/html.(*Tokenizer).skipWhiteSpace -- 01.09% [7697] compress/flate.(*decompressor).huffmanBlock @ /usr/home/tsgan/go/bin/shuultuur 00.01% [1] compress/flate.(*decompressor).huffmanBlock 01.01% [7184] strings.Map @ /usr/home/tsgan/go/bin/shuultuur 00.93% [6613] bitbucket.org/hooray-976/shuultuur/tools/search.(*stringFinder).next @ /usr/home/tsgan/go/bin/shuultuur 00.92% [6488] runtime.step @ /usr/home/tsgan/go/bin/shuultuur 00.62% [40] runtime.pcvalue 00.42% [27] runtime.goparkunlock 00.08% [5] github.com/elazarl/goproxy.func.018 00.03% [2] net/http.(*Server).ListenAndServeTLS -- ... I run FreeBSD current in VMware Fusion: root@bsd:/var/tmp # uname -an FreeBSD bsd 11.0-CURRENT FreeBSD 11.0-CURRENT #0 r269824: Mon Aug 11 20:18:52 UTC 2014 root@grind.freebsd.org:/usr/obj/usr/src/sys/GENERIC amd64 Maybe it depends from your use case?
Try something in C? I was seeing this even with nginx under load.
It looks like when program isn't compiled with debug symbols pmcstat won't resolve. Please try following with nginx: 1. Before compiling and installing nginx from ports run make clean. 1. Then run make config to choose DEBUG option additionally. 2. Run make 3. Depending from shell do similar way: env DONTSTRIP=1 make install or: setenv DONTSTRIP 1 && make install 4. Restart nginx Now start test with httperf to make load on nginx. Then run for instance: pmcstat -P INSTR_RETIRED_ANY -O /var/tmp/sample -t <nginx worker process pid> After while stop it and run: pmcstat -R /var/tmp/sample -G /var/tmp/sample.callgraph to generate callgraph or: pmcstat -R /var/tmp/sample -F /var/tmp/sample.calltree if you want calltree. I was successfully able to get callgraph and also calltree with resolved nginx symbols. ... 01.04% [350] ngx_vslprintf @ /usr/local/sbin/nginx 73.43% [257] ngx_sprintf 48.25% [124] ngx_http_time 100.0% [124] ngx_http_header_filter 100.0% [124] ngx_http_chunked_header_filter 100.0% [124] ngx_http_range_header_filter 100.0% [124] ngx_http_gzip_header_filter 100.0% [124] ngx_http_ssi_header_filter 100.0% [124] ngx_http_charset_header_filter 100.0% [124] ngx_http_userid_filter 100.0% [124] ngx_http_headers_filter 100.0% [124] ngx_http_not_modified_header_filter 100.0% [124] ngx_http_send_header 100.0% [124] ngx_http_static_handler 100.0% [124] ngx_http_core_content_phase 100.0% [124] ngx_http_core_run_phases 19.84% [51] ngx_http_header_filter 100.0% [51] ngx_http_chunked_header_filter 100.0% [51] ngx_http_range_header_filter 100.0% [51] ngx_http_gzip_header_filter 100.0% [51] ngx_http_ssi_header_filter 100.0% [51] ngx_http_charset_header_filter 100.0% [51] ngx_http_userid_filter 100.0% [51] ngx_http_headers_filter 100.0% [51] ngx_http_not_modified_header_filter 100.0% [51] ngx_http_send_header 100.0% [51] ngx_http_static_handler 100.0% [51] ngx_http_core_content_phase 100.0% [51] ngx_http_core_run_phases 100.0% [51] ngx_http_handler 17.12% [44] ngx_http_set_etag 100.0% [44] ngx_http_static_handler 100.0% [44] ngx_http_core_content_phase 100.0% [44] ngx_http_core_run_phases 100.0% [44] ngx_http_handler 100.0% [44] ngx_http_internal_redirect 100.0% [44] ngx_http_index_handler 100.0% [44] ngx_http_core_content_phase 100.0% [44] ngx_http_core_run_phases 100.0% [44] ngx_http_handler 100.0% [44] ngx_http_process_request 100.0% [44] ngx_http_process_request_headers 100.0% [44] ngx_http_process_request_line ...
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
This should be fixed now.
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