1 / 43

Profiling Suspicious Code

Profiling Suspicious Code. Tom Bascom White Star Software. A Few Words about the Speaker. Tom Bascom; Progress 4gl coder & roaming DBA since 1987 President, DBAppraise, LLC Remote database management service for OpenEdge .

marcus
Download Presentation

Profiling Suspicious Code

An Image/Link below is provided (as is) to download presentation Download Policy: Content on the Website is provided to you AS IS for your information and personal use and may not be sold / licensed / shared on other websites without getting consent from its author. Content is provided to you AS IS for your information and personal use only. Download presentation by click this link. While downloading, if for some reason you are not able to download a presentation, the publisher may have deleted the file from their server. During download, if you can't get a presentation, the file might be deleted by the publisher.

E N D

Presentation Transcript

  1. Profiling Suspicious Code Tom Bascom White Star Software

  2. A Few Words about the Speaker • Tom Bascom; Progress 4gl coder & roaming DBA since 1987 • President, DBAppraise, LLC • Remote database management service for OpenEdge. • Simplifying the job of managing and monitoring the world’s best business applications. • tom@dbappraise.com • VP, White Star Software, LLC • Expert consulting services related to all aspects of Progress and OpenEdge. • tom@wss.com

  3. Users want the right answer, with the best response time at the lowest cost.

  4. The performance enhancement possible with a given improvement is limited by the fraction of the execution time that the improved feature is used. -- Amdahl’s Law

  5. Performance is not just about the database. The most bang for the performance tuning buck is often in the application code. But figuring out where to look is often hard.

  6. Target the largest response time component of the most important Business process first.

  7. Some Tools

  8. Finding “Likely Suspects” • User Complaints • Compile with XREF • compile “program.p” xref “tmp/program.xrf” debug-list “tmp/program.dbg”. • “I/O By User” Data • CRUD Data • Testing – Add Performance Criteria to Test Plans for New Releases

  9. XREF c:\examples\t5.p 1 COMPILE c:/profiler/examples/t5.p c:\examples\t5.p 1 CPINTERNAL ISO8859-1 c:\examples\t5.p 1 CPSTREAM ISO8859-1 c:\examples\t5.p 7 STRING "i" 1 NONE UNTRANSLATABLE c:\examples\t5.p 13 STRING "Customer" 8 NONE UNTRANSLATABLE c:\examples\t5.p 13 ACCESS sports2000.Customer Phone c:\examples\t5.p 13 STRING "603 547 9574" 12 NONE TRANSLATABLE c:\examples\t5.p 13 SEARCH sports2000.Customer CustNum WHOLE-INDEX c:\examples\t5.p 15 STRING "->,>>>,>>9" 10 NONE TRANSLATABLE FORMAT c:\examples\t5.p 15 STRING "->,>>>,>>9" 10 NONE TRANSLATABLE FORMAT c:\examples\t5.p 17 STRING "t5" 2 NONE TRANSLATABLE c:\examples\t5.p 17 STRING "x(2)" 4 NONE TRANSLATABLE FORMAT c:\examples\t5.p 22 STRING "i" 1 LEFT TRANSLATABLE c:\examples\t5.p 22 STRING "----------" 10 NONE UNTRANSLATABLE c:\examples\t5.p 22 STRING "CustNum" 7 NONE UNTRANSLATABLE

  10. PROMON – IO By Process 04/08/04 I/O Operations by Process 11:00:00 -------- Database ----- ---- BI ----- ---- AI ----- Usr Name Access Read Write Read Write Read Write 0 lakewood 103183 3650 249 827 2999 1 3013 5 1 0 0 0 0 0 0 6 1 0 0 0 5214 0 0 7 1 0 0 0 5235 0 5244 8 1 0 22174 0 0 0 0 9 1 0 13935 0 0 0 0 10 lakewood 5443 7 0 0 0 0 0 11 lakewood 641020 635 0 0 0 0 0 12 lakewood 9441 30 0 0 0 0 0 13 smcnulty 143485322840 0 0 0 0 0 14 eratclif 366293 475 0 0 0 0 0 15 7326 108 0 0 0 0 0 16 sstout 213516997709 1 3 4 0 1 17 lakewood 42841 77 0 0 0 0 0 18 lakewood 138850 1262 0 0 0 0 0 19 aracey 788646 1171 0 0 0 0 0 20 lakewood 263693 422 0 1 0 0 0

  11. ProTop – IO By User 09:37:10 ProTop -- Progress Database Monitor (release xv) 09/19/04 Sample sports2000 [/data/s2k/sports2000] Rate Hit Ratio: 16:1 15:1 Commits: 65 20 Local: 51 Miss% : 6.448% 6.708% Latch Waits: 37 13 Remote: 0 Hit% : 93.552% 93.292% Tot/Mod Bufs: 1002 370 Batch: 50 Log Reads: 20067 13999 Evict Bufs: 10625 330 Server: 0 OS Reads: 1294 939 Lock Table: 8192 11 Other: 1 Chkpts: 0 0 Lock Tbl HWM: 138 TRX: 1 Flushed: 0 0 Old/Curr BI: 6140 6140 Blocked: 1 Area Full: 1 100.00% After Image: DISABLED Total: 52 UIO Usr Name Flags PID DB Access OS Reads OS Writes Hit% ----- --------------- ----- ------ ---------- ---------- ---------- ------- 31 julia SB 2776 4109 244 5 94.07% 30 jami SB 2772 2171 131 7 93.99% 34 tucker SB 2788 2003 126 3 93.72% 9 tucker SB* 2656 1315 106 28 91.94% 6 julia SB 2644 984 60 0 93.90% 32 peter SB 2780 900 62 2 93.13% 16 julia SB 2684 452 4 0 99.12%

  12. ProTop – CRUD Data 09:38:33 ProTop -- Progress Database Monitor (release xv) 09/19/04 Sample sports2000 [/data/s2k/sports2000] Rate Hit Ratio: 14:1 14:1 Commits: 62 65 Local: 51 Miss% : 7.239% 7.140% Latch Waits: 45 46 Remote: 0 Hit% : 92.761% 92.860% Tot/Mod Bufs: 1002 370 Batch: 50 Log Reads: 22960 26486 Evict Bufs: 26602 6225 Server: 0 OS Reads: 1662 1891 Lock Table: 8192 11 Other: 1 Chkpts: 1 0 Lock Tbl HWM: 138 TRX: 1 Flushed: 0 0 Old/Curr BI: 6141 6141 Blocked: 5 Area Full: 1 100.00% After Image: DISABLED Total: 52 Table Statistics Tbl# Table Name Create Read Update Delete ---- -------------------- --------- --------- --------- --------- 4 OrderLine 0 5937 152 0 24 POLine 0 2641 56 0 23 PurchaseOrder 0 1699 36 0 18 Order 0 1608 37 0 21 Bin 0 286 14 0 2 Customer 0 206 16 0 12 Vacation 0 111 5 0

  13. Why “Logical I/O” ??? • Consistent and Repeatable Measurement • The same query against any given dataset will always return the same result. • Not subject to external factors such as CPU speed, disk throughput, user activity or the buffer cache hit ratio. • Shows Hidden Problems even with small datasets. • Shows Impact on Other Users. • “Chokepoint” on rate of Logical IO ops.

  14. Why NOT etime() ??? • Non-Repeatable • Subject to a host of external factors • CPU speed, disk throughput, other user activity, buffer cache efficiency, phase of the moon • Granularity is too gross (millisecond) • Does measure non-db activity…

  15. LRTEST.p define variable i as integer no-undo. define variable lr as integer no-undo. find _myconnection no-lock. find _userio no-lock where _userio-usr = _myconn-userid no-error. lr = _userio._userio-dbaccess. etime( yes ). find <table> no-lock where <whatever> no-error. find _userio no-lock where _userio-usr = _myconn-userid no-error. display i ( _userio-dbaccess - lr ) etime().

  16. Example

  17. The performance enhancement possible with a given improvement is limited by the fraction of the execution time that the improved feature is used. -- Amdahl’s Law

  18. Target the largest response time component of the most important Business process first.

  19. Wouldn’t it be nice if… Description: XYZZY Date: 10/04/11 Top Total Time Lines Program Line Avg Time Time Calls ------------------------------ ----- ----------- ---------- ------- xtabsms2.p 19281 93.256652 186.513304 2 getdocprep2.p 939 63.346967 126.693934 2 proc_create_sitm xtabsms2.p 11926 12.611345 50.445380 4 xtcountry_x2_x3.p 359 0.000013 0.459658 34,967 proc_read-database sysval.p 536 0.000117 0.336606 2,879 xtcountry_x2_x3.p 360 0.000009 0.324163 34,894 getdocprep2.p 741 0.067411 0.269642 4 proc_upd_nref xtmfintb2.p 3582 0.003438 0.233802 68 proc_upd_nref xtmfintb2.p 3298 0.003137 0.213345 68 proc_process_tasks xttskscn.r 3091 0.012560 0.200956 16 findClient sysval.p 328 0.000094 0.165167 1,763

  20. The Profiler

  21. Profiler • First introduced with version 8.2 (-zprofile) • “Unsupported” (meaning the analysis tool) • Improved with version 9.0 (session:profiler handle, no more -zecret) • Microsecond timings • Does not include “think time”

  22. Using the Profiler • -profile • Non-intrusive • Non-selective • profiler: handle • Selective • But requires code insertion or “wrappering” • Analysis tools • $DLC/src/samples/profiler • http://www.greenfieldtech.com/downloads

  23. PROFILER Attributes • DESCRIPTION – optional text describing this session • LISTINGS – whether or not to create debug listings • DIRECTORY – where to create debug listings (default to –T) • FILE-NAME – name of output file (default profile.out) • ENABLED – yes/no; initializes listings and so forth • PROFILING – turn profiling on or off

  24. Other PROFILER Attributes • TRACE-FILTER – CSV list of “matches” criteria for procedure tracing • TRACING – line level tracing • COVERAGE - % coverage support

  25. PROFILER Methods • Write-Data() – flush accumulated data to output file. • User-Data(char) – write user defined data, such as VST statistics, to the output file.

  26. Minimal Embedded Usage assign profiler:enabled = yes profiler:profiling = yes .do i = 1 to 1000000: /* do something */end. assign profiler:enabled = no profiler:profiling = no .profiler:write-data().

  27. Targeted Profiling • Embedded in Code Being Investigated define variable i as integer no-undo. run profiler/on.p ( “batch001” ). do i = 1 to 10: find customer no-lock where customer.cust-num = 1 no-error. end. do i = 1 to 10: find customer no-lock where customer.phone = "(702) 272-9264" no-error. end. run profiler/off.p ( “batch001” ).

  28. Unsupported Profiling Utility

  29. Profiling a Session • Create file called profiler.cfg with 3 lines: -OUTFILE /tmp/profiler.out -LISTINGS /tmp -DESCRIBE someDescription • Add –profile to session startup: mpro dbName –p start.p –profile profiler.cfg • Run normally. • Terminate cleanly & analyze the output.

  30. Sample Profiling Output Description: XYZZY Date: 10/04/11 Top Total Time Lines Program Line Avg Time Time Calls ------------------------------ ----- ----------- ---------- ------- xtabsms2.p 19281 93.256652 186.513304 2 getdocprep2.p 939 63.346967 126.693934 2 proc_create_sitm xtabsms2.p 11926 12.611345 50.445380 4 xtcountry_x2_x3.p 359 0.000013 0.459658 34,967 proc_read-database sysval.p 536 0.000117 0.336606 2,879 xtcountry_x2_x3.p 360 0.000009 0.324163 34,894 getdocprep2.p 741 0.067411 0.269642 4 proc_upd_nref xtmfintb2.p 3582 0.003438 0.233802 68 proc_upd_nref xtmfintb2.p 3298 0.003137 0.213345 68 proc_process_tasks xttskscn.r 3091 0.012560 0.200956 16 findClient sysval.p 328 0.000094 0.165167 1,763

  31. Profiler ExampleA Calculation Bottleneck? 1 1 1 1 p = 4 * ( 1 - --- + --- - --- + --- ... ) 3 5 7 9

  32. Profiler ExampleA Calculation Bottleneck? 0009 function piterm returns decimal ( input n as integer ). 0010 return ( 1.0 / (( n * 2 ) + 1 )). 0011 end. 0012 0013 do while abs( newpi - oldpi ) > precision: 0014 oldpi = newpi. 0015 if i modulo 2 = 0 then 0016 pi = pi + piterm( i ). 0017 else 0018 pi = pi - piterm( i ). 0019 newpi = ( 4.0 * pi ). 0020 display i newpi oldpi. 0021 i = i + 1. 0022 end.

  33. Sample Profiling Output Description: pi Date: 10/07/11 Top Total Time Lines Program Line Avg Time Time Calls ------------------------------ ----- ----------- ---------- ------- ./pi.p 20 0.0001593.183243 20,001 piterm ./pi.p 10 0.000010 0.197060 20,001 ./pi.p 13 0.000006 0.114640 20,002 ./pi.p 18 0.000010 0.097591 10,000 ./pi.p 16 0.000009 0.094585 10,001 ./pi.p 15 0.000004 0.082780 20,001 ./pi.p 19 0.000004 0.080964 20,001 ./pi.p 21 0.000004 0.076913 20,001 ./pi.p 14 0.000002 0.036911 20,001 /home/tom/p26226_Untitled1.ped 1 0.009446 0.018891 2 piterm ./pi.p 11 0.000001 0.017755 20,001 ./pi.p 22 0.000001 0.013877 20,001

  34. Profiler ExampleA Calculation Bottleneck? 0009 function piterm returns decimal ( input n as integer ). 0010 return ( 1.0 / (( n * 2 ) + 1 )). 0011 end. 0012 0013 do while abs( newpi - oldpi ) > precision: 0014 oldpi = newpi. 0015 if i modulo 2 = 0 then 0016 pi = pi + piterm( i ). 0017 else 0018 pi = pi - piterm( i ). 0019 newpi = ( 4.0 * pi ). 0020 if i modulo 100 = 0 then display i newpi oldpi. 0021 i = i + 1. 0022 end.

  35. Sample Profiling Output Description: pi Date: 10/07/11 Top Total Time Lines Program Line Avg Time Time Calls ------------------------------ ----- ----------- ---------- ------- piterm ./pi.p 10 0.000010 0.193776 20,001 ./pi.p 13 0.000005 0.106857 20,002 ./pi.p 18 0.000009 0.087636 10,000 ./pi.p 16 0.000009 0.087096 10,001 ./pi.p 20 0.000004 0.083103 20,001 ./pi.p 19 0.000004 0.079651 20,001 ./pi.p 15 0.000004 0.078491 20,001 ./pi.p 21 0.000003 0.058005 20,001 ./pi.p 14 0.000002 0.036486 20,001 piterm ./pi.p 11 0.000001 0.016168 20,001 ./pi.p 22 0.000001 0.011794 20,001

  36. Caveat! define variable i as integer no-undo.assign profiler:enabled = yes profiler:profiling = yes .do i = 1 to 1000000:end.i = 0.do while i < 1000000: i = i + 1.end.i = 0. do while i < 1000000: i = i + 1. end.assign profiler:enabled = no profiler:profiling = no.profiler:write-data().

  37. Caveat! 1 02/28/2007 "Generic" 07:55:03 "tom".2 "profile.p" "" 63126.0 0 2 1.0 0 1 0.000000 30.9358282 11 1 0.000002 0.0000022 8 1000001 4.607678 4.6076782 9 1000000 1.719586 1.7195862 14 1000000 1.501487 1.5014872 12 1000001 3.013981 3.0139812 13 1000000 3.032433 3.0324332 16 1 0.000003 0.000003....

  38. Reminders & Hints • Line numbers are DEBUG LISTING line numbers • You need to have .DBG files • They need to be created with the same source and PROPATH as your .r files • Session profiling must terminate cleanly – no “kill” & no crash. • Temp files can become very, very large.

  39. Summary • Things to be suspicious of. • Tools to narrow your search. • A better way to gauge query effectiveness. • An introduction to Profiling. • Strategies for attacking code performance problems.

  40. Target the largest response time component of the most important Business process first.

  41. ? Questions

  42. There is no silver bullet. -- Fred Brooks You just have to be persistent. -- Tom Bascom

  43. Thank you for your time!tom@wss.comhttp://wss.com

More Related