Techniques for Investigating Suspicious Code

1. Techniquesfor Investigating Suspicious Code Tom Bascom President, Greenfield Technologies

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

3. Or as The Engine Crew says: • Performance • Performance • Performance…

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. Target the largest response time component of the most important Business process first.

6. Performance is not, however, 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.

7. 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

8. 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

9. 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

10. 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%

11. 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

12. 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…

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. 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().

15. Example

16. Demo!

17. The Wall • At a very low level the Database Manager’s “storage engine” is single threaded – all access to blocks must pass through “latches”.

18. Pick An Index, Any Index… http://www.allegroconsultants.com/presentations/

19. Profiler • First introduced with version 8.2 (-zprofile) • “Unsupported” • Improved with version 9.0 (profiler: handle) • Microsecond timings • Does not include “think time”

20. 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

21. Sample Profiling Output Description: Profiling Sample 001 Date: 04/08/06 Top Average Time lines Program Line Avg Time Time Calls ------------------------------ ----- ------------- ------------- ---------- examples/t4.p 7 0.006963 0.006963 1 examples/t.p 47 0.001577 0.006307 4 examples/t.p 45 0.001449 0.004347 3 examples/t2.p 14 0.001133 0.001133 1 examples/t.p 43 0.000625 0.002498 4 examples/t3.p 7 0.000484 0.000484 1 examples/t2.p 17 0.000283 0.000283 1 examples/t.p 42 0.000191 0.000763 4 examples/t2.p 15 0.000071 0.000071 1 examples/t2.p 10 0.000055 0.054935 1,001 applhelp.p 1 0.000053 0.000053 1 examples/t.p 40 0.000043 0.000128 3 examples/t2.p 11 0.000037 0.037202 1,000

22. 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” ).

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

24. Demo!

25. Profiler ExampleA Calculation Bottleneck? function piterm returns decimal ( input n as integer ). return ( 1.0 / (( n * 2 ) + 1 )). end. do while abs( newpi - oldpi ) > precision: oldpi = newpi. i = i + 1. if i modulo 2 = 0 then pi = pi + piterm( i ). else pi = pi - piterm( i ). newpi = ( 4.0 * pi ). display newpi oldpi. end.

26. Addressing The Problem • Improve Query Criteria • Adding Indexes • Re-Design the Program or Algorithm • De-Normalize the Data • Tune Client Parameters • Treat the Symptoms

27. Improving the Query • Use Indexed Fields • Use Equality Matches • Use Leading Components of Indexes • Use Multiple Indexes • Eliminate Functions in WHERE Clauses

28. Adding Indexes • Don’t Be Afraid!!! • Single Component Indexes • Storage Areas • But DO Be Careful… • Some (small) Overhead Involved • Possible to Break Existing Queries • Gratuitous FIRST/LAST Are Dangerous • USE-INDEX Can Fix – But Beware! • Use BY If Order Matters

29. Redesign the Program • Eliminate Multiple Passes Through Data • Use Temp-Tables • Summary Data • A Repository of Details from 1st Pass • Joined Data • Are Ranges Sensible? • “NEXT” is often a Red Flag. • Eliminate Unnecessary Joins

30. De-Normalize the Data • Create Summary Fields • Add Fields for Frequently Calculated Values • Add Fields or Even Tables for Redundant Data (current status vs status history) • ASSIGN triggers can make this safer – logic embedded in UI is an inherently unsafe method.

31. Tune Client Parameters • Individualize Client Parameters • Bt – temp-table buffer • mmax – client side sorting & selection • Consider Using Private Buffers • Minimize Interference with Others

32. Treat the Symptoms • Process in the Background • Provide a Progress Indicator • Purge Data If there is data that can be purged and its existence impacts the runtime of a program that doesn’t need it (after all it can be purged…) then that program has a problem that we’ve already covered… But a purge may be a cost effective short-term solution.

33. 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.

34. There is no silver bullet. -- Fred Brooks But there are some hidden vents ;-) -- Tom Bascom

35. ? Questions

37. Thank you for your time!tom@greenfieldtech.comhttp://www.greenfieldtech.com