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. -- Amdahls 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/t
  5.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 "-gt,gtgtgt,gtgt9" 10 NONE
  TRANSLATABLE FORMAT
• c\examples\t5.p 15 STRING "-gt,gtgtgt,gtgt9" 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
• 110000
• -------- 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 1434853 22840 0 0
  0 0 0
• 14 eratclif 366293 475 0 0
  0 0 0
• 15 7326 108 0 0
  0 0 0
• 16 sstout 21351699 7709 1 3
  4 0 1
• 17 lakewood 42841 77 0 0
  0 0 0

10
ProTop IO By User
093710 ProTop -- Progress Database
Monitor (release xv) 09/19/04 Sample
sports2000 /data/s2k/sports2000
Rate Hit Ratio 161 151
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
093833 ProTop -- Progress Database
Monitor (release xv) 09/19/04 Sample
sports2000 /data/s2k/sports2000
Rate Hit Ratio 141 141
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 lttablegt no-lock where ltwhatevergt no-error.
• find _userio no-lock where
• _userio-usr _myconn-userid no-error.
• display i ( _userio-dbaccess - lr ) etime().

15
Example
for each loanfile no-lock where loan-amount gt 500000 Records Log I/O Ratio etime()
Production 383 335,597 8761 6,685ms2,788ms
Development 41 28517 6951 647ms394ms
QA 365 327284 8961 4,880ms2,965ms
for each loanfile no-lock where price-locked gt 12/01/2006 and price-locked lt 12/31/2006
Production 1,498 3,001 21 64ms52ms
Development 0 3 N/A 19ms0ms
QA 1,501 3,010 21 64ms52ms
16
Demo!
17
The Wall

• At a very low level the Database Managers
  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
  "[phone]" 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 ) gt
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

• Dont 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
doesnt need it (after all it can be purged)
then that program has a problem that weve
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
36
(No Transcript)
37
Thank you for your time!tom_at_greenfieldtech.comh
ttp//www.greenfieldtech.com