Docstoc

suspicious

Document Sample
suspicious Powered By Docstoc
					     Techniques
                      for

   Investigating
Suspicious Code
         Tom Bascom
   President, Greenfield
          Technologies
Users want the right
answer, with the best
response time at the
lowest cost.
Or as The Engine Crew says:


     Performance

     Performance

     Performance…
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
Target the largest response
time component of the
most important Business
process first.
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.
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
 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
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    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
 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
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%
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
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…
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.
 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().
Example
                                                    Records   Log I/O   Ratio   etime()
for each loanfile no-lock where
    loan-amount > 500000:


                                       Production    383      335,597   876:1   6,685ms
                                                                                2,788ms

                                     Development      41      28517     695:1   647ms
                                                                                394ms

                                             QA      365      327284    896:1   4,880ms
                                                                                2,965ms

for each loanfile no-lock where
    price-locked >= 12/01/2006 and
    price-locked <= 12/31/2006:

                                       Production    1,498     3,001     2:1     64ms
                                                                                 52ms

                                     Development      0         3       N/A      19ms
                                                                                 0ms

                                             QA      1,501     3,010     2:1     64ms
                                                                                 52ms
Demo!
The Wall
   At a very low level                            Readprobe - Dell N530
    the Database
                                          120000
    Manager’s “storage                    100000




                          Logical Reads
    engine” is single                     80000

    threaded – all                        60000
                                          40000
    access to blocks                      20000
    must pass through                         0




                                                           10
                                                                15
                                                                     20
                                                                          25
                                                                               30
                                                                                    35
                                                                                         40
                                                                                              45
                                                                                                   50
                                                   0
                                                       5
    “latches”.                                                       Sessions
 Pick An Index, Any Index…




http://www.allegroconsultants.com/presentations/
Profiler

   First introduced with version 8.2 (-zprofile)
   “Unsupported”
   Improved with version 9.0 (profiler: handle)
   Microsecond timings
   Does not include “think time”
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
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
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” ).
Profiler Example
A Calculation Bottleneck?


                1    1      1     1
 p = 4 * ( 1 - --- + --- - --- + --- ... )
                3    5      7     9
Demo!
Profiler Example
A 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.
Addressing The Problem
   Improve Query Criteria
   Adding Indexes
   Re-Design the Program or Algorithm
   De-Normalize the Data
   Tune Client Parameters
   Treat the Symptoms
Improving the Query
   Use Indexed Fields
   Use Equality Matches
   Use Leading Components of Indexes
   Use Multiple Indexes
   Eliminate Functions in WHERE Clauses
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
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
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.
Tune Client Parameters
   Individualize Client Parameters
       Bt – temp-table buffer
       mmax – client side sorting & selection


   Consider Using Private Buffers
       Minimize Interference with Others
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.
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.
There is no silver bullet.
                    -- Fred Brooks

But there are some hidden
vents ;-)
                   -- Tom Bascom
Questions
  Thank you for
   your time!
   tom@greenfieldtech.com
http://www.greenfieldtech.com