[Bug runtime/10665] New: backtrace() is too slow

[Bug runtime/10665] New: backtrace() is too slow

[wcohen at redhat dot com]

Trying to use backtrace() for bz6960 so that the code is portable between
different kernels. However, the backtrace() function is so slow that the script
skips probe handlers way too often and exits the script.

Looking through the code for the backtrace() it flushes the buffer, uses the 
normal print to buffer and then copy things from the buffer. That has some overhead.

-- 
           Summary: backtrace() is too slow
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: wcohen at redhat dot com
OtherBugsDependingO 6960
             nThis:


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2009-09-18 21:42 -------
Created an attachment (id=4213)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=4213&action=view)
Latencytap script demoing the slow backtrace and skips

Will see that a number of probes skipped with:

stap -vt latencytap5slow.stp

Replace the backtrace() with "0" and see that the script no longer skips
probes.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2009-09-18 21:56 -------
Created an attachment (id=4214)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=4214&action=view)
Non-probe-skipping skript

Here are the timing results for the slow non-working version and the
fast version with the backtrace() removed.

$ stap -v /tmp/latencytap5slow.stp
...
Pass 5: starting run.
WARNING: Number of errors: 0, skipped probes: 101
WARNING: Skipped due to global 'this_sleep' lock timeout: 101
Starting data collection
mode - All Pids

probe kernel.trace("deactivate_task")!+1 (/tmp/latencytap5slow.stp:16:1), hits:
92, cycles: 936min/2159avg/5841max
probe kernel.trace("activate_task")!+1 (/tmp/latencytap5slow.stp:25:1), hits:
96, cycles: 1377min/232381avg/575271max
probe scheduler.cpu_on (/tmp/latencytap5slow.stp:38:1), hits: 131, cycles:
648min/1898954avg/33218154max
probe begin (/tmp/latencytap5slow.stp:60:1), hits: 1, cycles:
4833min/4833avg/4833max
Pass 5: run completed in 20usr/60sys/623real ms.



$ stap -vt /tmp/latencytap5fast.stp 
...
Pass 5: starting run.
Starting data collection
mode - All Pids

^C
7413 354619 7388 0x0000000000000000 
probe kernel.trace("deactivate_task")!+1 (/tmp/latencytap5fast.stp:16:1), hits:
7500, cycles: 783min/3600avg/11097max
probe kernel.trace("activate_task")!+1 (/tmp/latencytap5fast.stp:25:1), hits:
7486, cycles: 936min/4534avg/11673max
probe scheduler.cpu_on (/tmp/latencytap5fast.stp:38:1), hits: 11855, cycles:
405min/1507avg/5787max
probe end (/tmp/latencytap5fast.stp:48:1), hits: 1, cycles:
44577min/44577avg/44577max
probe begin (/tmp/latencytap5fast.stp:60:1), hits: 1, cycles:
3483min/3483avg/3483max
Pass 5: run completed in 10usr/50sys/9150real ms.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2009-09-18 21:59 -------
(Just for completeness, it'd be interesting to see an elapsed get_cycles()
display before & after the backtrace() call.)

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[wcohen at redhat dot com]

------- Additional Comments From wcohen at redhat dot com  2009-09-18 23:41 -------
Created an attachment (id=4216)
 --> (http://sourceware.org/bugzilla/attachment.cgi?id=4216&action=view)
Really stripped down script showing overhead of backtrace()

To get an idea of how expensive an backtrace() is stripped down the script to
just the minimal probe on scheduler.cpu_on with backtrace() and surround with
get_cycles() calls.

$ stap	/tmp/latencytap5cycles2.stp
cycles 777420
cycles 3896271
cycles 6780348
cycles 3861072
cycles 4474818
cycles 4476204
cycles 3861855
cycles 5818356
cycles 2236599
cycles 645948
cycles 3858462
cycles 3848517
cycles 2239398
cycles 4477878
cycles 2241936
cycles 3848400
cycles 760986
cycles 3987090
cycles 3869181
cycles 3860586
cycles 3859299
cycles 2232333
cycles 2231253
cycles 3844926
cycles 3843081
cycles 3350403
cycles 5239485
cycles 962775
cycles 5779449
cycles 5772330
cycles 5784822
cycles 6713838
cycles 3357648
cycles 5788287
cycles 8726688
cycles 2367684
cycles 4429449
cycles 641565
cycles 5820147
cycles 3880998
cycles 2234718
cycles 3867669
cycles 3844017
cycles 2234043
cycles 3860514
cycles 2231685
cycles 642618
cycles 3844881
cycles 4405986
cycles 3864267
cycles 5898744
cycles 3861009
cycles 4474899
cycles 2232783
cycles 641403
cycles 4358808
cycles 4478643
cycles 5822703
cycles 3857229
cycles 3844800
cycles 3864393
cycles 651195
cycles 2234313
cycles 3859470
cycles 5901246
cycles 4394277
cycles 3136716
cycles 5799609
cycles 4406805
cycles 3870891
cycles 4414896
cycles 4475574
cycles 3122541
cycles 3861729
cycles 4403070
cycles 3117843
cycles 3866589
cycles 3853881
cycles 3845727
cycles 3110256
cycles 3845160
cycles 4388319
cycles 4405734
cycles 3120102
cycles 3862746
cycles 2239992
cycles 4409541
cycles 3844575
cycles 3121857
cycles 759951
cycles 4409577
cycles 3177288
cycles 3866121
cycles 4410828
cycles 3861432
cycles 2234268
cycles 759024
cycles 3121533
cycles 4409559
cycles 3179376
cycles 3870279
cycles 760068
cycles 4411638
cycles 3175299
cycles 3862881
cycles 4408416
cycles 3860253
cycles 2233368
cycles 759159
cycles 3120813
cycles 4415103
cycles 3175605
cycles 3845124
cycles 760239
cycles 4408470
cycles 3857796
cycles 3864807
cycles 3925305
cycles 1902672
cycles 3860118
cycles 3177315
cycles 2232648
cycles 4410558
cycles 3844746
cycles 2231199
cycles 5902353
cycles 3845286
cycles 758898
cycles 4478256
cycles 4475547
cycles 763155
cycles 5905728
cycles 3864321
cycles 5899122
cycles 764037
cycles 3846969
cycles 1899945
cycles 4476177
cycles 3175965
cycles 3861900
cycles 4408236
cycles 3856203
cycles 4397571
cycles 4388832
cycles 3174561
cycles 3852477
cycles 2238858
cycles 4409316
cycles 3845916
cycles 759969
cycles 3863871
cycles 3855303
cycles 1926324
cycles 3867777
cycles 3175938
cycles 3863214
cycles 4411719
cycles 2237472
cycles 3121074
cycles 3848625
cycles 759186
cycles 4410855
cycles 3179124
cycles 4413546
cycles 3866535
cycles 3910581
cycles 3861504
cycles 3862377
cycles 1899117
cycles 2232522
cycles 3174957
cycles 3861450
cycles 761940
cycles 4410450
cycles 3177171
cycles 4415580
cycles 3175299
cycles 3876021
cycles 3867696
cycles 3845556
cycles 3859830
cycles 2237769
cycles 3849858
cycles 1904139
cycles 4389912
cycles 3846312
cycles 3173040
cycles 759762
cycles 4408587
cycles 3119553
cycles 3181527
cycles 3868281
cycles 3862215
cycles 3861639
cycles 1899963
cycles 3862602
cycles 2233728
cycles 3843441
cycles 759870
cycles 3112281
cycles 4429593
cycles 4417290
cycles 5900769
cycles 3181131
cycles 3863691
cycles 3862710
cycles 3861333
cycles 1899360
cycles 3862710
cycles 2234538
cycles 3858507
cycles 761751
cycles 3110382
cycles 4479354
cycles 4476438
cycles 4477986
cycles 3121371
cycles 3864816
cycles 3860910
cycles 3860010
cycles 1895976
cycles 3851379
cycles 2240100
cycles 3851820
cycles 762039
cycles 3120183
cycles 4422447
cycles 3117600
cycles 4431771
cycles 3177099
cycles 3865986
cycles 3861540
cycles 3860019
cycles 3844431
cycles 3852252
cycles 1898163
cycles 759456
cycles 4475745
cycles 3866139
cycles 2257839
cycles 3867705
cycles 762678
cycles 3176496
cycles 4410207
cycles 3125916
cycles 3867156
cycles 4411170
cycles 3859398
cycles 3119481
cycles 3850551
cycles 1899396
cycles 759969
cycles 4407525
cycles 3882762
cycles 3877992
cycles 2268081
cycles 3174354
cycles 3865446
cycles 762165
cycles 4414356
cycles 3924909
cycles 3857580
cycles 3863592
cycles 2233503
cycles 3109086
cycles 5900751
cycles 4397490
cycles 3914127
cycles 3126114
cycles 4273785
cycles 3855114
cycles 4406625
cycles 3110427
cycles 3850056
cycles 3855717
cycles 5899635
cycles 1905444
cycles 3845349
cycles 5904144
cycles 3869406
cycles 6636042
cycles 3848139
cycles 2236860
cycles 6683355
cycles 3176757
cycles 5909292
cycles 6687513
cycles 3854556
cycles 3860478
cycles 3846681
cycles 3846474
cycles 2241027
cycles 1897533
cycles 3853647
cycles 1902762
cycles 3845655
cycles 761256
cycles 13332879
cycles 4452831
cycles 3852882
cycles 3868605
cycles 3851730
cycles 3860595
cycles 1897182
cycles 2235114
cycles 3852333
cycles 762183
cycles 13223862
cycles 652212
cycles 3890637
cycles 763902
cycles 3863457
cycles 3847059
cycles 3876552
cycles 1904346
cycles 762246
cycles 3863547
cycles 2243916
cycles 3873762
cycles 4477653
cycles 763002
cycles 2246058
cycles 6677424
cycles 765909
cycles 5804640
cycles 656721
cycles 3894021
cycles 4479237
cycles 646209
cycles 3863619
cycles 4477113
cycles 3851028
cycles 5821893
cycles 5901453
cycles 3861054
cycles 5858964
cycles 3856833
cycles 2237589
cycles 5907627
cycles 5795883
cycles 5910849
cycles 4396266
cycles 3176694
cycles 3852216
cycles 3857121
cycles 5909760
cycles 2244681
cycles 4396491
cycles 5910201
cycles 2238120
cycles 3115503
cycles 4475943
cycles 4392765
cycles 5854653
cycles 3116331
cycles 3198834
cycles 5922468
cycles 4483197
cycles 6679683
cycles 4477878
cycles 4480821
cycles 5902542
cycles 5902929
cycles 6679287
cycles 4486095
cycles 5903541
cycles 5821506
cycles 5900823
cycles 4409064
cycles 6923124
cycles 6112845
cycles 5908914
cycles 4400136
cycles 3110103
cycles 5906979
cycles 3856446
cycles 3848535
cycles 6679611
cycles 2237490
cycles 5899806
cycles 5899815
cycles 13320909
cycles 6677577
cycles 4475880
cycles 5902371
cycles 5825295
cycles 4473207
cycles 5913549
cycles 5909085
cycles 3866643
cycles 1911888
cycles 3846618
cycles 5904081
cycles 762012
cycles 4479111
cycles 5822307
cycles 6689187
cycles 3868596
cycles 5898357
ERROR: probe overhead exceeded threshold
ERROR: probe overhead exceeded threshold
WARNING: Number of errors: 2, skipped probes: 0
cycles 3862971
cycles 1903491
cycles 5901867
cycles 3863016
cycles 763371
cycles 4483485
cycles 3180762
cycles 3868686
cycles 3866670
cycles 3903768
cycles 3861720
cycles 5898654
cycles 3848589
cycles 1902483
cycles 3867975
cycles 2235780
cycles 3848454
cycles 1897173
cycles 761130
cycles 6635817
cycles 4475115
cycles 3862809
cycles 764532
cycles 6678639
cycles 5906736
cycles 3865212
cycles 4477194
cycles 3874626
cycles 3863574
cycles 3846375
cycles 3863799
cycles 1900089
cycles 761337
cycles 2240964
cycles 5814801
cycles 3886794
cycles 3865734
cycles 3867741
cycles 2236086
cycles 3862719
cycles 1899666
cycles 5901687
cycles 3845790
cycles 5902209


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[mjw at redhat dot com]

------- Additional Comments From mjw at redhat dot com  2009-10-28 13:12 -------
The dwarf based unwinder does too much work during runtime, some of it should be
moved into the translator, which can also optimise some stuff.

Currently both the debug_frame and eh_frame tables are scanned linearly to find
the FDE (frame description entry) that covers the current PC. There are several
sanity checks while walking the tables and reading the FDE and CIE entries. And
for eh_frame table data all load address bases start addresses are adjusted
because the tables are loaded at a different address at runtime (in the kernel).
Although there is some support for using eh_framhdr indexes (so we don't need to
do a linear search) it isn't used (the addresses would adjustment and
debug_frame tables don't have hdr indexes).

All the above can be done at translation time. The debug_frame and eh_frame
tables can be combined and one hdr index table can be created. While doing that
the FDE and CIE entries can be sanity checked so we know they are clean/trusted
at runtime. And any load address relative addressing can be changed to a
relative encoding.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[fche at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
OtherBugsDependingO|                            |11179
              nThis|                            |


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[alexl at redhat dot com]

------- Additional Comments From alexl at redhat dot com  2010-01-19 10:54 -------
ubacktrace() is no speed demon either, hopefully performance fixes to
backtrace() fixes ubacktrace() too.

Also, moving as much work as possible to the translator is very important. I had
a test script that at each GObject construction time the stored the backtrace in
an array based on the pointer, then freed it at finalize time. Then at program
shutdown we can print the stacktraces of all leaked objects. This means almost
no backtraces are actually translated, so any computation that can be moved to
translation is a huge gain.

I *was* able to run the above script, but i had to disable/increase all sort of
system limitations for it to work.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/10665] backtrace() is too slow

[fche at redhat dot com]

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |fche at redhat dot com
         AssignedTo|systemtap at sources dot    |mjw at redhat dot com
                   |redhat dot com              |
             Status|NEW                         |ASSIGNED


http://sourceware.org/bugzilla/show_bug.cgi?id=10665

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.