SQL for Period Aggregate Reporting

Posted on by
Reply

[There is a recording on this article here: Tweet, and also in my GitHub project, Small SQL projects.]

Update 16 November 2021: I added dynamic SQL solutions to this, including 21c SQL macro, and ported to my new GitHub blog: SQL for Period Aggregate Reporting (GitHub blog)

In financial reporting there is often a requirement to report on sales performance across multiple time periods. For example we might want to know total sales of products for a given month, then for the 3 month period, the year to date, and the 12 month period up to that month, etc.. We might also want to break down associated costs of selling across the same periods. There are several ways to approach implementing such reports in SQL, and in real world applications that may have many columns and periods to report on, different approaches will have different levels of complexity and performance characteristics. In this article I will describe three approaches, starting with perhaps the most obvious one, which is to write a Group By query for each period type and combine them all in a union. This obvious approach involves quite a few repeated scans of the source table, so we will describe two other approaches that are less obvious, but avoid so many scans and should be better performing. We’ll use a simple set of generated test data to illustrate the three queries, and will provide the execution plans associated with each one.

Test Data

We take two products and generate three years of monthly sales and cost values randomly between fixed limits in each case. Here is the generation code, for the table and first product (script c_sales_history.sql):

CREATE TABLE sales_history (
        prod_code               VARCHAR2(30) NOT NULL,
        month_dt                DATE NOT NULL,
        sales_value             NUMBER(10,0),
        sales_cost              NUMBER(10,0),
        CONSTRAINT slh_pk       PRIMARY KEY (prod_code, month_dt)
)
/
PROMPT 3 years random values for PROD_ONE
INSERT INTO sales_history
WITH month_gen AS (
    SELECT LEVEL rn, Add_Months(Trunc(SYSDATE, 'MONTH'), LEVEL - 36) dt
      FROM DUAL
   CONNECT BY LEVEL < 37 ) SELECT 'PROD_ONE', dt, DBMS_Random.Value (low => 1000, high => 10000),
       DBMS_Random.Value (low => 100, high => 1000)
  FROM month_gen
/

Here is the table data generated, with running sums of the two measures, that can help in testing the queries:

Sales History Report with Running Sums

Product    Month          Value Value to Date     Cost Cost to Date
---------- ----------- -------- ------------- -------- ------------
PROD_ONE   01-MAR-18      9,004         9,004      800          800
           01-APR-18      8,757        17,761      766        1,566
           01-MAY-18      5,748        23,509      835        2,401
           01-JUN-18      6,931        30,440      436        2,837
           01-JUL-18      4,717        35,157      115        2,952
           01-AUG-18      2,309        37,466      478        3,430
           01-SEP-18      1,415        38,881      253        3,683
           01-OCT-18      8,767        47,648      122        3,805
           01-NOV-18      4,560        52,208      547        4,352
           01-DEC-18      2,656        54,864      783        5,135
           01-JAN-19      9,984        64,848      401        5,536
           01-FEB-19      8,131        72,979      381        5,917
           01-MAR-19      2,063        75,042      191        6,108
           01-APR-19      2,933        77,975      147        6,255
           01-MAY-19      7,058        85,033      997        7,252
           01-JUN-19      7,941        92,974      392        7,644
           01-JUL-19      2,270        95,244      949        8,593
           01-AUG-19      2,586        97,830      921        9,514
           01-SEP-19      8,912       106,742      109        9,623
           01-OCT-19      4,018       110,760      272        9,895
           01-NOV-19      8,056       118,816      807       10,702
           01-DEC-19      8,497       127,313      880       11,582
           01-JAN-20      5,266       132,579      888       12,470
           01-FEB-20      1,636       134,215      532       13,002
           01-MAR-20      5,241       139,456      287       13,289
           01-APR-20      8,519       147,975      579       13,868
           01-MAY-20      4,034       152,009      245       14,113
           01-JUN-20      4,633       156,642      107       14,220
           01-JUL-20      8,906       165,548      169       14,389
           01-AUG-20      8,126       173,674      281       14,670
           01-SEP-20      8,319       181,993      487       15,157
           01-OCT-20      7,273       189,266      599       15,756
           01-NOV-20      9,646       198,912      390       16,146
           01-DEC-20      3,988       202,900      933       17,079
           01-JAN-21      2,626       205,526      278       17,357
           01-FEB-21      2,943       208,469      262       17,619
PROD_TWO   01-MAR-18      3,546         3,546      115          115
           01-APR-18      6,627        10,173      525          640
           01-MAY-18      2,892        13,065      877        1,517
           01-JUN-18      8,132        21,197      630        2,147
           01-JUL-18      3,778        24,975      145        2,292
           01-AUG-18      6,258        31,233      109        2,401
           01-SEP-18      2,425        33,658      257        2,658
           01-OCT-18      3,983        37,641      118        2,776
           01-NOV-18      1,181        38,822      971        3,747
           01-DEC-18      2,015        40,837      723        4,470
           01-JAN-19      4,966        45,803      129        4,599
           01-FEB-19      7,711        53,514      770        5,369
           01-MAR-19      1,966        55,480      249        5,618
           01-APR-19      8,129        63,609      689        6,307
           01-MAY-19      1,669        65,278      358        6,665
           01-JUN-19      6,936        72,214      779        7,444
           01-JUL-19      3,023        75,237      515        7,959
           01-AUG-19      1,039        76,276      593        8,552
           01-SEP-19      1,220        77,496      276        8,828
           01-OCT-19      6,371        83,867      268        9,096
           01-NOV-19      2,142        86,009      438        9,534
           01-DEC-19      2,897        88,906      974       10,508
           01-JAN-20      6,446        95,352      126       10,634
           01-FEB-20      6,163       101,515      983       11,617
           01-MAR-20      3,607       105,122      500       12,117
           01-APR-20      6,558       111,680      659       12,776
           01-MAY-20      3,075       114,755      965       13,741
           01-JUN-20      9,317       124,072      451       14,192
           01-JUL-20      2,639       126,711      476       14,668
           01-AUG-20      2,143       128,854      356       15,024
           01-SEP-20      2,347       131,201      507       15,531
           01-OCT-20      4,090       135,291      580       16,111
           01-NOV-20      5,598       140,889      630       16,741
           01-DEC-20      6,018       146,907      264       17,005
           01-JAN-21      4,339       151,246      935       17,940
           01-FEB-21      2,860       154,106      232       18,172

72 rows selected.

Group By Union Query

Here is the first query:

SELECT /*+ gather_plan_statistics XPLAN_MARKER_UGB */ 
     month_dt, prod_code, 'P1 - 1 Month' per_tp, sales_value, sales_cost
  FROM sales_history
UNION ALL
SELECT drv.month_dt, drv.prod_code, 'P2 - 3 Months', Sum(msr.sales_value), Sum(msr.sales_cost)
  FROM sales_history drv
  JOIN sales_history msr
  ON msr.prod_code = drv.prod_code
   AND msr.month_dt BETWEEN Add_Months (drv.month_dt, -2) AND drv.month_dt
 GROUP BY drv.prod_code, drv.month_dt
UNION ALL
SELECT drv.month_dt, drv.prod_code, 'P3 - YTD', Sum(msr.sales_value), Sum(msr.sales_cost)
  FROM sales_history drv
  JOIN sales_history msr
  ON msr.prod_code = drv.prod_code
   AND msr.month_dt BETWEEN Trunc(drv.month_dt, 'YEAR') AND drv.month_dt
 GROUP BY drv.prod_code, drv.month_dt
UNION ALL
SELECT drv.month_dt, drv.prod_code, 'P4 - 1 Year', Sum(msr.sales_value), Sum(msr.sales_cost)
  FROM sales_history drv
  JOIN sales_history msr
  ON msr.prod_code = drv.prod_code
   AND msr.month_dt BETWEEN Add_Months (drv.month_dt, -11) AND drv.month_dt
 GROUP BY drv.prod_code, drv.month_dt
 ORDER BY 1, 2, 3

Notes on Group By Union Query

  • First union member subquery does not aggregate, and includes the label for the period type
  • The remainig aggregation subqueries drive from one scan of the table and join a second instance
  • The second instance has the date range for the period type in its join condition
  • The gather_plan_statistics hint allows capture of plan statistics
  • The XPLAN_MARKER_UGB is a string used to identify the SQL id to pass to the API for displaying the plan

Here are the results from the first query (script period_agg_report_queries.sql), which are the same for the other two queries.

Periods Report by Union of Group Bys

Month       Product    Period             Value     Cost
----------- ---------- --------------- -------- --------
01-MAR-18   PROD_ONE   P1 - 1 Month       9,004      800
                       P2 - 3 Months      9,004      800
                       P3 - YTD           9,004      800
                       P4 - 1 Year        9,004      800
            PROD_TWO   P1 - 1 Month       3,546      115
                       P2 - 3 Months      3,546      115
                       P3 - YTD           3,546      115
                       P4 - 1 Year        3,546      115
01-APR-18   PROD_ONE   P1 - 1 Month       8,757      766
                       P2 - 3 Months     17,761    1,566
                       P3 - YTD          17,761    1,566
                       P4 - 1 Year       17,761    1,566
            PROD_TWO   P1 - 1 Month       6,627      525
                       P2 - 3 Months     10,173      640
                       P3 - YTD          10,173      640
                       P4 - 1 Year       10,173      640
01-MAY-18   PROD_ONE   P1 - 1 Month       5,748      835
                       P2 - 3 Months     23,509    2,401
                       P3 - YTD          23,509    2,401
                       P4 - 1 Year       23,509    2,401
            PROD_TWO   P1 - 1 Month       2,892      877
                       P2 - 3 Months     13,065    1,517
                       P3 - YTD          13,065    1,517
                       P4 - 1 Year       13,065    1,517
01-JUN-18   PROD_ONE   P1 - 1 Month       6,931      436
                       P2 - 3 Months     21,436    2,037
                       P3 - YTD          30,440    2,837
                       P4 - 1 Year       30,440    2,837
            PROD_TWO   P1 - 1 Month       8,132      630
                       P2 - 3 Months     17,651    2,032
                       P3 - YTD          21,197    2,147
                       P4 - 1 Year       21,197    2,147
01-JUL-18   PROD_ONE   P1 - 1 Month       4,717      115
                       P2 - 3 Months     17,396    1,386
                       P3 - YTD          35,157    2,952
                       P4 - 1 Year       35,157    2,952
            PROD_TWO   P1 - 1 Month       3,778      145
                       P2 - 3 Months     14,802    1,652
                       P3 - YTD          24,975    2,292
                       P4 - 1 Year       24,975    2,292
01-AUG-18   PROD_ONE   P1 - 1 Month       2,309      478
                       P2 - 3 Months     13,957    1,029
                       P3 - YTD          37,466    3,430
                       P4 - 1 Year       37,466    3,430
            PROD_TWO   P1 - 1 Month       6,258      109
                       P2 - 3 Months     18,168      884
                       P3 - YTD          31,233    2,401
                       P4 - 1 Year       31,233    2,401
01-SEP-18   PROD_ONE   P1 - 1 Month       1,415      253
                       P2 - 3 Months      8,441      846
                       P3 - YTD          38,881    3,683
                       P4 - 1 Year       38,881    3,683
            PROD_TWO   P1 - 1 Month       2,425      257
                       P2 - 3 Months     12,461      511
                       P3 - YTD          33,658    2,658
                       P4 - 1 Year       33,658    2,658
01-OCT-18   PROD_ONE   P1 - 1 Month       8,767      122
                       P2 - 3 Months     12,491      853
                       P3 - YTD          47,648    3,805
                       P4 - 1 Year       47,648    3,805
            PROD_TWO   P1 - 1 Month       3,983      118
                       P2 - 3 Months     12,666      484
                       P3 - YTD          37,641    2,776
                       P4 - 1 Year       37,641    2,776
01-NOV-18   PROD_ONE   P1 - 1 Month       4,560      547
                       P2 - 3 Months     14,742      922
                       P3 - YTD          52,208    4,352
                       P4 - 1 Year       52,208    4,352
            PROD_TWO   P1 - 1 Month       1,181      971
                       P2 - 3 Months      7,589    1,346
                       P3 - YTD          38,822    3,747
                       P4 - 1 Year       38,822    3,747
01-DEC-18   PROD_ONE   P1 - 1 Month       2,656      783
                       P2 - 3 Months     15,983    1,452
                       P3 - YTD          54,864    5,135
                       P4 - 1 Year       54,864    5,135
            PROD_TWO   P1 - 1 Month       2,015      723
                       P2 - 3 Months      7,179    1,812
                       P3 - YTD          40,837    4,470
                       P4 - 1 Year       40,837    4,470
01-JAN-19   PROD_ONE   P1 - 1 Month       9,984      401
                       P2 - 3 Months     17,200    1,731
                       P3 - YTD           9,984      401
                       P4 - 1 Year       64,848    5,536
            PROD_TWO   P1 - 1 Month       4,966      129
                       P2 - 3 Months      8,162    1,823
                       P3 - YTD           4,966      129
                       P4 - 1 Year       45,803    4,599
01-FEB-19   PROD_ONE   P1 - 1 Month       8,131      381
                       P2 - 3 Months     20,771    1,565
                       P3 - YTD          18,115      782
                       P4 - 1 Year       72,979    5,917
            PROD_TWO   P1 - 1 Month       7,711      770
                       P2 - 3 Months     14,692    1,622
                       P3 - YTD          12,677      899
                       P4 - 1 Year       53,514    5,369
01-MAR-19   PROD_ONE   P1 - 1 Month       2,063      191
                       P2 - 3 Months     20,178      973
                       P3 - YTD          20,178      973
                       P4 - 1 Year       66,038    5,308
            PROD_TWO   P1 - 1 Month       1,966      249
                       P2 - 3 Months     14,643    1,148
                       P3 - YTD          14,643    1,148
                       P4 - 1 Year       51,934    5,503
01-APR-19   PROD_ONE   P1 - 1 Month       2,933      147
                       P2 - 3 Months     13,127      719
                       P3 - YTD          23,111    1,120
                       P4 - 1 Year       60,214    4,689
            PROD_TWO   P1 - 1 Month       8,129      689
                       P2 - 3 Months     17,806    1,708
                       P3 - YTD          22,772    1,837
                       P4 - 1 Year       53,436    5,667
01-MAY-19   PROD_ONE   P1 - 1 Month       7,058      997
                       P2 - 3 Months     12,054    1,335
                       P3 - YTD          30,169    2,117
                       P4 - 1 Year       61,524    4,851
            PROD_TWO   P1 - 1 Month       1,669      358
                       P2 - 3 Months     11,764    1,296
                       P3 - YTD          24,441    2,195
                       P4 - 1 Year       52,213    5,148
01-JUN-19   PROD_ONE   P1 - 1 Month       7,941      392
                       P2 - 3 Months     17,932    1,536
                       P3 - YTD          38,110    2,509
                       P4 - 1 Year       62,534    4,807
            PROD_TWO   P1 - 1 Month       6,936      779
                       P2 - 3 Months     16,734    1,826
                       P3 - YTD          31,377    2,974
                       P4 - 1 Year       51,017    5,297
01-JUL-19   PROD_ONE   P1 - 1 Month       2,270      949
                       P2 - 3 Months     17,269    2,338
                       P3 - YTD          40,380    3,458
                       P4 - 1 Year       60,087    5,641
            PROD_TWO   P1 - 1 Month       3,023      515
                       P2 - 3 Months     11,628    1,652
                       P3 - YTD          34,400    3,489
                       P4 - 1 Year       50,262    5,667
01-AUG-19   PROD_ONE   P1 - 1 Month       2,586      921
                       P2 - 3 Months     12,797    2,262
                       P3 - YTD          42,966    4,379
                       P4 - 1 Year       60,364    6,084
            PROD_TWO   P1 - 1 Month       1,039      593
                       P2 - 3 Months     10,998    1,887
                       P3 - YTD          35,439    4,082
                       P4 - 1 Year       45,043    6,151
01-SEP-19   PROD_ONE   P1 - 1 Month       8,912      109
                       P2 - 3 Months     13,768    1,979
                       P3 - YTD          51,878    4,488
                       P4 - 1 Year       67,861    5,940
            PROD_TWO   P1 - 1 Month       1,220      276
                       P2 - 3 Months      5,282    1,384
                       P3 - YTD          36,659    4,358
                       P4 - 1 Year       43,838    6,170
01-OCT-19   PROD_ONE   P1 - 1 Month       4,018      272
                       P2 - 3 Months     15,516    1,302
                       P3 - YTD          55,896    4,760
                       P4 - 1 Year       63,112    6,090
            PROD_TWO   P1 - 1 Month       6,371      268
                       P2 - 3 Months      8,630    1,137
                       P3 - YTD          43,030    4,626
                       P4 - 1 Year       46,226    6,320
01-NOV-19   PROD_ONE   P1 - 1 Month       8,056      807
                       P2 - 3 Months     20,986    1,188
                       P3 - YTD          63,952    5,567
                       P4 - 1 Year       66,608    6,350
            PROD_TWO   P1 - 1 Month       2,142      438
                       P2 - 3 Months      9,733      982
                       P3 - YTD          45,172    5,064
                       P4 - 1 Year       47,187    5,787
01-DEC-19   PROD_ONE   P1 - 1 Month       8,497      880
                       P2 - 3 Months     20,571    1,959
                       P3 - YTD          72,449    6,447
                       P4 - 1 Year       72,449    6,447
            PROD_TWO   P1 - 1 Month       2,897      974
                       P2 - 3 Months     11,410    1,680
                       P3 - YTD          48,069    6,038
                       P4 - 1 Year       48,069    6,038
01-JAN-20   PROD_ONE   P1 - 1 Month       5,266      888
                       P2 - 3 Months     21,819    2,575
                       P3 - YTD           5,266      888
                       P4 - 1 Year       67,731    6,934
            PROD_TWO   P1 - 1 Month       6,446      126
                       P2 - 3 Months     11,485    1,538
                       P3 - YTD           6,446      126
                       P4 - 1 Year       49,549    6,035
01-FEB-20   PROD_ONE   P1 - 1 Month       1,636      532
                       P2 - 3 Months     15,399    2,300
                       P3 - YTD           6,902    1,420
                       P4 - 1 Year       61,236    7,085
            PROD_TWO   P1 - 1 Month       6,163      983
                       P2 - 3 Months     15,506    2,083
                       P3 - YTD          12,609    1,109
                       P4 - 1 Year       48,001    6,248
01-MAR-20   PROD_ONE   P1 - 1 Month       5,241      287
                       P2 - 3 Months     12,143    1,707
                       P3 - YTD          12,143    1,707
                       P4 - 1 Year       64,414    7,181
            PROD_TWO   P1 - 1 Month       3,607      500
                       P2 - 3 Months     16,216    1,609
                       P3 - YTD          16,216    1,609
                       P4 - 1 Year       49,642    6,499
01-APR-20   PROD_ONE   P1 - 1 Month       8,519      579
                       P2 - 3 Months     15,396    1,398
                       P3 - YTD          20,662    2,286
                       P4 - 1 Year       70,000    7,613
            PROD_TWO   P1 - 1 Month       6,558      659
                       P2 - 3 Months     16,328    2,142
                       P3 - YTD          22,774    2,268
                       P4 - 1 Year       48,071    6,469
01-MAY-20   PROD_ONE   P1 - 1 Month       4,034      245
                       P2 - 3 Months     17,794    1,111
                       P3 - YTD          24,696    2,531
                       P4 - 1 Year       66,976    6,861
            PROD_TWO   P1 - 1 Month       3,075      965
                       P2 - 3 Months     13,240    2,124
                       P3 - YTD          25,849    3,233
                       P4 - 1 Year       49,477    7,076
01-JUN-20   PROD_ONE   P1 - 1 Month       4,633      107
                       P2 - 3 Months     17,186      931
                       P3 - YTD          29,329    2,638
                       P4 - 1 Year       63,668    6,576
            PROD_TWO   P1 - 1 Month       9,317      451
                       P2 - 3 Months     18,950    2,075
                       P3 - YTD          35,166    3,684
                       P4 - 1 Year       51,858    6,748
01-JUL-20   PROD_ONE   P1 - 1 Month       8,906      169
                       P2 - 3 Months     17,573      521
                       P3 - YTD          38,235    2,807
                       P4 - 1 Year       70,304    5,796
            PROD_TWO   P1 - 1 Month       2,639      476
                       P2 - 3 Months     15,031    1,892
                       P3 - YTD          37,805    4,160
                       P4 - 1 Year       51,474    6,709
01-AUG-20   PROD_ONE   P1 - 1 Month       8,126      281
                       P2 - 3 Months     21,665      557
                       P3 - YTD          46,361    3,088
                       P4 - 1 Year       75,844    5,156
            PROD_TWO   P1 - 1 Month       2,143      356
                       P2 - 3 Months     14,099    1,283
                       P3 - YTD          39,948    4,516
                       P4 - 1 Year       52,578    6,472
01-SEP-20   PROD_ONE   P1 - 1 Month       8,319      487
                       P2 - 3 Months     25,351      937
                       P3 - YTD          54,680    3,575
                       P4 - 1 Year       75,251    5,534
            PROD_TWO   P1 - 1 Month       2,347      507
                       P2 - 3 Months      7,129    1,339
                       P3 - YTD          42,295    5,023
                       P4 - 1 Year       53,705    6,703
01-OCT-20   PROD_ONE   P1 - 1 Month       7,273      599
                       P2 - 3 Months     23,718    1,367
                       P3 - YTD          61,953    4,174
                       P4 - 1 Year       78,506    5,861
            PROD_TWO   P1 - 1 Month       4,090      580
                       P2 - 3 Months      8,580    1,443
                       P3 - YTD          46,385    5,603
                       P4 - 1 Year       51,424    7,015
01-NOV-20   PROD_ONE   P1 - 1 Month       9,646      390
                       P2 - 3 Months     25,238    1,476
                       P3 - YTD          71,599    4,564
                       P4 - 1 Year       80,096    5,444
            PROD_TWO   P1 - 1 Month       5,598      630
                       P2 - 3 Months     12,035    1,717
                       P3 - YTD          51,983    6,233
                       P4 - 1 Year       54,880    7,207
01-DEC-20   PROD_ONE   P1 - 1 Month       3,988      933
                       P2 - 3 Months     20,907    1,922
                       P3 - YTD          75,587    5,497
                       P4 - 1 Year       75,587    5,497
            PROD_TWO   P1 - 1 Month       6,018      264
                       P2 - 3 Months     15,706    1,474
                       P3 - YTD          58,001    6,497
                       P4 - 1 Year       58,001    6,497
01-JAN-21   PROD_ONE   P1 - 1 Month       2,626      278
                       P2 - 3 Months     16,260    1,601
                       P3 - YTD           2,626      278
                       P4 - 1 Year       72,947    4,887
            PROD_TWO   P1 - 1 Month       4,339      935
                       P2 - 3 Months     15,955    1,829
                       P3 - YTD           4,339      935
                       P4 - 1 Year       55,894    7,306
01-FEB-21   PROD_ONE   P1 - 1 Month       2,943      262
                       P2 - 3 Months      9,557    1,473
                       P3 - YTD           5,569      540
                       P4 - 1 Year       74,254    4,617
            PROD_TWO   P1 - 1 Month       2,860      232
                       P2 - 3 Months     13,217    1,431
                       P3 - YTD           7,199    1,167
                       P4 - 1 Year       52,591    6,555

288 rows selected.

Here is the execution plan:

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation             | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |               |      1 |        |    288 |00:00:00.01 |      27 |       |       |          |
|   1 |  SORT ORDER BY        |               |      1 |    225 |    288 |00:00:00.01 |      27 | 27648 | 27648 |24576  (0)|
|   2 |   UNION-ALL           |               |      1 |        |    288 |00:00:00.01 |      27 |       |       |          |
|   3 |    TABLE ACCESS FULL  | SALES_HISTORY |      1 |     72 |     72 |00:00:00.01 |       6 |       |       |          |
|   4 |    HASH GROUP BY      |               |      1 |     51 |     72 |00:00:00.01 |       7 |   934K|   934K| 1401K (0)|
|*  5 |     HASH JOIN         |               |      1 |     67 |    210 |00:00:00.01 |       7 |  1506K|  1506K|  787K (0)|
|   6 |      INDEX FULL SCAN  | SLH_PK        |      1 |     72 |     72 |00:00:00.01 |       1 |       |       |          |
|   7 |      TABLE ACCESS FULL| SALES_HISTORY |      1 |     72 |     72 |00:00:00.01 |       6 |       |       |          |
|   8 |    HASH GROUP BY      |               |      1 |     51 |     72 |00:00:00.01 |       7 |   934K|   934K| 1401K (0)|
|*  9 |     HASH JOIN         |               |      1 |     67 |    428 |00:00:00.01 |       7 |  1506K|  1506K|  789K (0)|
|  10 |      INDEX FULL SCAN  | SLH_PK        |      1 |     72 |     72 |00:00:00.01 |       1 |       |       |          |
|  11 |      TABLE ACCESS FULL| SALES_HISTORY |      1 |     72 |     72 |00:00:00.01 |       6 |       |       |          |
|  12 |    HASH GROUP BY      |               |      1 |     51 |     72 |00:00:00.01 |       7 |   934K|   934K| 1408K (0)|
|* 13 |     HASH JOIN         |               |      1 |     67 |    732 |00:00:00.01 |       7 |  1506K|  1506K|  787K (0)|
|  14 |      INDEX FULL SCAN  | SLH_PK        |      1 |     72 |     72 |00:00:00.01 |       1 |       |       |          |
|  15 |      TABLE ACCESS FULL| SALES_HISTORY |      1 |     72 |     72 |00:00:00.01 |       6 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
5 - access("MSR"."PROD_CODE"="DRV"."PROD_CODE")
filter(("MSR"."MONTH_DT"<="DRV"."MONTH_DT" AND "MSR"."MONTH_DT">=ADD_MONTHS(INTERNAL_FUNCTION("DRV"."MONTH_DT
"),-2)))
9 - access("MSR"."PROD_CODE"="DRV"."PROD_CODE")
filter(("MSR"."MONTH_DT"<="DRV"."MONTH_DT" AND "MSR"."MONTH_DT">=TRUNC(INTERNAL_FUNCTION("DRV"."MONTH_DT"),'f
myear')))
13 - access("MSR"."PROD_CODE"="DRV"."PROD_CODE")
filter(("MSR"."MONTH_DT"<="DRV"."MONTH_DT" AND "MSR"."MONTH_DT">=ADD_MONTHS(INTERNAL_FUNCTION("DRV"."MONTH_DT
"),-11)))

Notes on Group By Union Query Execution Plan

  • There are 4 full table scans, and 3 index full scans
  • The Buffers value of 27 is a measure of the work done, in logical I/O operations

Analytic Functions and Unpivot Query

Here is the second query:

WITH period_aggs AS (
  SELECT /*+ gather_plan_statistics XPLAN_MARKER_AAG */ 
       month_dt, prod_code, sales_value, 
       Sum(sales_value) OVER (PARTITION BY prod_code ORDER BY month_dt
                  RANGE BETWEEN INTERVAL '2' MONTH PRECEDING AND CURRENT ROW)     sales_value_3m, 
       Sum(sales_value) OVER (PARTITION BY prod_code, Trunc(month_dt, 'YEAR') ORDER BY month_dt
                  RANGE BETWEEN INTERVAL '11' MONTH PRECEDING AND CURRENT ROW)    sales_value_ytd, 
       Sum(sales_value) OVER (PARTITION BY prod_code ORDER BY month_dt
                  RANGE BETWEEN INTERVAL '11' MONTH PRECEDING AND CURRENT ROW)    sales_value_1y, 
       sales_cost,
       Sum(sales_cost) OVER (PARTITION BY prod_code ORDER BY month_dt
                  RANGE BETWEEN INTERVAL '2' MONTH PRECEDING AND CURRENT ROW)     sales_cost_3m, 
       Sum(sales_cost) OVER (PARTITION BY prod_code, Trunc(month_dt, 'YEAR') ORDER BY month_dt
                  RANGE BETWEEN INTERVAL '11' MONTH PRECEDING AND CURRENT ROW)    sales_cost_ytd, 
       Sum(sales_cost) OVER (PARTITION BY prod_code ORDER BY month_dt
                  RANGE BETWEEN INTERVAL '11' MONTH PRECEDING AND CURRENT ROW)    sales_cost_1y
    FROM sales_history
)
SELECT *
  FROM period_aggs
UNPIVOT (
    (sales_value, sales_cost)
    FOR per_tp IN (
      (sales_value, sales_cost)         AS 'P1 - 1 Month',
      (sales_value_3m, sales_cost_3m)   AS 'P2 - 3 Months',
      (sales_value_ytd, sales_cost_ytd) AS 'P3 - YTD',
      (sales_value_1y, sales_cost_1y)   AS 'P4 - 1 Year'
    )
)
 ORDER BY 1, 2, 3

Notes on Analytic Functions and Unpivot Query

  • For each measure a column is added for each period type to do the aggregation via analytic functions
  • The UNPIVOT clause in the main query converts the period type columns into rows with column pair as specified in the first line
  • The column name pair is specified in the first line for the unpivoted row values
  • The ‘FOR per_tp IN’ clauses specifies the name of the period type column with values given in the rows below

Here is the execution plan:

----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |               |      1 |        |    288 |00:00:00.01 |       2 |       |       |          |
|   1 |  SORT ORDER BY                    |               |      1 |    288 |    288 |00:00:00.01 |       2 | 27648 | 27648 |24576  (0)|
|*  2 |   VIEW                            |               |      1 |    288 |    288 |00:00:00.01 |       2 |       |       |          |
|   3 |    UNPIVOT                        |               |      1 |        |    288 |00:00:00.01 |       2 |       |       |          |
|   4 |     VIEW                          |               |      1 |     72 |     72 |00:00:00.01 |       2 |       |       |          |
|   5 |      WINDOW SORT                  |               |      1 |     72 |     72 |00:00:00.01 |       2 | 13312 | 13312 |12288  (0)|
|   6 |       WINDOW BUFFER               |               |      1 |     72 |     72 |00:00:00.01 |       2 |  6144 |  6144 | 6144  (0)|
|   7 |        TABLE ACCESS BY INDEX ROWID| SALES_HISTORY |      1 |     72 |     72 |00:00:00.01 |       2 |       |       |          |
|   8 |         INDEX FULL SCAN           | SLH_PK        |      1 |     72 |     72 |00:00:00.01 |       1 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter(("unpivot_view_006"."SALES_VALUE" IS NOT NULL OR "unpivot_view_006"."SALES_COST" IS NOT NULL))

Notes on Execution Plan for Analytic Functions and Unpivot Query

  • There is a single index full scan and a single table access by index rowid
  • The number of buffers is only 2
  • The plan suggests that this query will be a lot more efficient than the first one

Single Group By with CASE Expressions Query

Here is the third query:

WITH period_list AS (
  SELECT month_dt, prod_code, COLUMN_VALUE per_tp
    FROM TABLE(SYS.ODCIVarchar2List(
          'P1 - 1 Month',
          'P2 - 3 Months',
          'P3 - YTD',
          'P4 - 1 Year')
      )
  CROSS JOIN (SELECT month_dt, prod_code FROM sales_history)
)
SELECT /*+ gather_plan_statistics XPLAN_MARKER_GBC */
       drv.month_dt, drv.prod_code, drv.per_tp,
       Sum( CASE WHEN ( per_tp = 'P1 - 1 Month'  AND msr.month_dt = drv.month_dt ) OR 
                      ( per_tp = 'P2 - 3 Months' AND msr.month_dt >= Add_Months (drv.month_dt, -2) ) OR 
                      ( per_tp = 'P3 - YTD'      AND Trunc (msr.month_dt, 'YEAR') = Trunc (drv.month_dt, 'YEAR') ) OR 
                      ( per_tp = 'P4 - 1 Year'   AND msr.month_dt >= Add_Months (drv.month_dt, -11) )
                 THEN msr.sales_value END) sales_value,
       Sum( CASE WHEN ( per_tp = 'P1 - 1 Month'  AND msr.month_dt = drv.month_dt ) OR 
                      ( per_tp = 'P2 - 3 Months' AND msr.month_dt >= Add_Months (drv.month_dt, -2) ) OR 
                      ( per_tp = 'P3 - YTD'      AND Trunc (msr.month_dt, 'YEAR') = Trunc (drv.month_dt, 'YEAR') ) OR 
                      ( per_tp = 'P4 - 1 Year'   AND msr.month_dt >= Add_Months (drv.month_dt, -11) )
                 THEN msr.sales_cost END) sales_cost
  FROM period_list drv
  JOIN sales_history msr
  ON msr.prod_code = drv.prod_code
   AND msr.month_dt <= drv.month_dt
 GROUP BY drv.prod_code, drv.month_dt, drv.per_tp
 ORDER BY 1, 2, 3

Notes on Single Group By with CASE Expressions Query

  • In the first subquery we add in the period type values for each product and month
  • The main query then includes the extra column in its grouping fields
  • The main query drives from the first subquery, joining the table to aggregate over, and including only records not later than the driving record
  • The CASE expressions within the Sums ensure that a measure is counted in the sum only if its date on the joined table falls in the required range for the period type, relative to the date in the driving subquery
------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                 | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                          |               |      1 |        |    288 |00:00:00.01 |       7 |       |       |          |
|   1 |  SORT GROUP BY                            |               |      1 |     51 |    288 |00:00:00.01 |       7 | 40960 | 40960 |36864  (0)|
|*  2 |   HASH JOIN                               |               |      1 |     10M|   5328 |00:00:00.01 |       7 |  1476K|  1476K|  826K (0)|
|   3 |    INDEX FULL SCAN                        | SLH_PK        |      1 |     72 |     72 |00:00:00.01 |       1 |       |       |          |
|   4 |    MERGE JOIN CARTESIAN                   |               |      1 |    588K|    288 |00:00:00.01 |       6 |       |       |          |
|   5 |     TABLE ACCESS FULL                     | SALES_HISTORY |      1 |     72 |     72 |00:00:00.01 |       6 |       |       |          |
|   6 |     BUFFER SORT                           |               |     72 |   8168 |    288 |00:00:00.01 |       0 |  2048 |  2048 | 2048  (0)|
|   7 |      COLLECTION ITERATOR CONSTRUCTOR FETCH|               |      1 |   8168 |      4 |00:00:00.01 |       0 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("MSR"."PROD_CODE"="PROD_CODE")
filter("MSR"."MONTH_DT"<="MONTH_DT")

Notes on Execution Plan for Single Group By with CASE Expressions Query

  • There is a single index full scan and a single full table access
  • The number of buffers is 7
  • The plan suggests that this query will also be a lot more efficient than the first one
  • The data set is too small to be conclusive regarding performance comparison with the second query

See also:






PL/SQL Profiling 4: Custom Code Timing

Posted on by
Reply

This article describes the use of a custom code timing PL/SQL package, Timer_Set, on two example program structures. The examples are designed to illustrate its behaviour over as many different scenarios as possible, while keeping the examples as simple as possible. It’s based on an article published in March 2013 on the hierarchical profiler and updated shortly thereafter with the inclusion of Oracle’s older flat profiler and of custom code timing. In June 2020 installation and source code were put onto GitHub, and the article was restructured into an overview article with the detail on the three profiling methods as separate articles, of which this is the third. Here are links to the other three articles:

PL/SQL Profiling 1: Overview
PL/SQL Profiling 2: Hierarchical Profiler
PL/SQL Profiling 3: Flat Profiler

All source code, including installation scripts, is available on GitHub:
GitHub: Oracle PL/SQL Profiling
Tweet with recording attached

For this custom code timing demonstration I created a new version of the package used by the the Oracle profiling demos, and driver scripts (prefixed ts_) for the same examples.

These use an ‘object-oriented’ timing package that I wrote a few years ago Timer_Set: Oracle PL/SQL code timing module on GitHub to instrument at procedure and section level. It is often considered good practice to implement timing and other instrumentation permanently in production code.

In both examples a new timer set object is created, calls are made to increment timers within the set, and at the end a report on the timings is written to log. The way the timer set operates in general is illustrated by a diagram taken from the GitHub module:

Setup

The GitHub project linked to above includes scripts for setup of prerequisites such as grants and tables, and for installation of the custom code used for this demonstration. As described in the overview article, there are two example scripts profiled.

  • Example 1: General. This covers a wide range of scenarios
  • Example 2: Sleep. This covers the particular example of DBMS_Lock.Sleep

Timer Set Data Model

A logical data model is shown below. There are no physical tables involved.

Example 1: General

The example was descibed in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
PROMPT B1: A_Calls_B 
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN
  Timer_Set_Test.Init;
  Timer_Set_Test.A_Calls_B(l_call_count);

END;
/
PROMPT SQL: Static DB function call
SELECT Timer_Set_Test.DBFunc
  FROM DUAL;

PROMPT B2: Static DB function; dynamic SQL; object constructor
DECLARE
  l_cur              SYS_REFCURSOR;
  l_ret_val          PLS_INTEGER;
  l_tab_count        Table_Count_Type;

BEGIN

  SELECT Timer_Set_Test.DBFunc
    INTO l_ret_val
    FROM DUAL;

  OPEN l_cur FOR 'SELECT Count(*) FROM all_tab_columns'; 
  Timer_Set_Test.Increment_Time('Open cursor');
  FETCH l_cur INTO l_ret_val; 
  Timer_Set_Test.Increment_Time('Fetch from cursor');
  CLOSE l_cur;
  Timer_Set_Test.Increment_Time('Close cursor');

  l_tab_count := Table_Count_Type('EMP');
  Timer_Set_Test.Increment_Time('Construct object');

END;
/
PROMPT B3: R_Calls_R; write times
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  Timer_Set_Test.R_Calls_R(l_call_count);

  Timer_Set_Test.Write_Times;

END;
/
SET TIMING OFF

The script is structured as an anonymous block, B1, then a stand-alone SQL query, followed by two more anonymous blocks, B2 and B3. The timer set is constructed in the first block within the call:

  Timer_Set_Test.Init

The script then increments timers at several points, again through calls to Timer_Set_Test, while Timer_Set_Test itself has timer calls inside. The results of the timing are listed at the end by the call:

  Timer_Set_Test.Write_Times;

Results for Example 1: General

Timer Set: Timer_Set_Test, Constructed at 27 Jun 2020 07:52:51, written at 07:52:52
===================================================================================
Timer                      Elapsed         CPU       Calls       Ela/Call       CPU/Call
----------------------  ----------  ----------  ----------  -------------  -------------
A_Calls_B, section one        0.01        0.02           2        0.00600        0.01000
A_Calls_B, section two        0.03        0.02           2        0.01450        0.01000
B_Calls_A: 2                  0.03        0.03           1        0.03100        0.03000
B_Calls_A: 4                  0.06        0.06           1        0.06100        0.06000
DBFunc                        0.08        0.06           2        0.03850        0.03000
Open cursor                   0.00        0.00           1        0.00100        0.00000
Fetch from cursor             0.27        0.29           1        0.27400        0.29000
Close cursor                  0.00        0.00           1        0.00000        0.00000
Construct object              0.03        0.01           1        0.02500        0.01000
R_Calls_R                     0.04        0.03           2        0.02000        0.01500
(Other)                       0.00        0.00           1        0.00100        0.00000
----------------------  ----------  ----------  ----------  -------------  -------------
Total                         0.55        0.52          15        0.03673        0.03467
----------------------  ----------  ----------  ----------  -------------  -------------
[Timer timed (per call in ms): Elapsed: 0.00971, CPU: 0.01068]

Notes on Output

  • Calls, CPU and elapsed times have been captured at the section level for A_Calls_B
  • Observe that, while R_Calls_R and A_Calls_B aggregate over all calls, B_Calls_A records values by call; this is implemented simply by including a value that changes with call in the timer name: 
      Increment_Time('B_Calls_A: ' || x_call_no);
  • The output shows how much of the elapsed time comes from CPU usage; in particular, note that R_Calls_R calls an inlined procedure Rest_a_While that does a square root operation in a loop to consume CPU time, and we can see that elapsed and CPU times are the same
  • The timer set object is designed to be very low footprint; here 9 statements (calls to Increment_Time), plus a small global overhead, produced 10 result lines, plus associated information
  • The Total line values are calculated using timing differences betwee reporting and construction of the timer set
  • The (Other) line values are calculated using the diffeences between the Total line values and the sums of the specific line values
  • The Timer timed line allows the overhead of the timing itself to be estimated
  • The ‘object-oriented’ approach allows multiple programs to be be timed at multiple levels, without interference between timings
  • Formatting such as column widths and decimal places can be specified as parameters in the reporting API call, and here take the default values

Example 2: Sleep

The example was described in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
PROMPT B1: Construct timer set; DBMS_Lock.Sleep, 3 + 6; insert to trigger_tab; write timer set
DECLARE
  l_timer_set       PLS_INTEGER;
BEGIN
  l_timer_set := Timer_Set.Construct('Profiling DBMS_Lock.Sleep');
  DBMS_Lock.Sleep(3);
  Timer_Set.Increment_Time(l_timer_set, '3 second sleep');

  INSERT INTO trigger_tab VALUES (2, 0.5);
  Timer_Set.Increment_Time(l_timer_set, 'INSERT INTO trigger_tab VALUES (2, 0.5)');

  DBMS_Lock.Sleep(6);
  Timer_Set.Increment_Time(l_timer_set, '6 second sleep');
  Utils.W(Timer_Set.Format_Results(l_timer_set));

END;
/
SET TIMING OFF

The script constructs a timer set, then makes calls to a system procedure, DBMS_Lock.Sleep, which sleeps without using CPU time, then inserts to a table with a Before Insert trigger that calls a custom sleep procedure, Utils.Sleep. Utils.Sleep itself calls DBMS_Lock.Sleep to do non-CPU sleeping and also runs a mathematical operation in a loop to use CPU time. Timers are incremented after each main call, and the results of the timing are writtten out at the end.

Results for Example 2: Sleep

Timer Set: Profiling DBMS_Lock.Sleep, Constructed at 27 Jun 2020 07:53:00, written at 07:53:11
==============================================================================================
Timer                                       Elapsed         CPU       Calls       Ela/Call       CPU/Call
---------------------------------------  ----------  ----------  ----------  -------------  -------------
3 second sleep                                 3.00        0.00           1        3.00000        0.00000
INSERT INTO trigger_tab VALUES (2, 0.5)        2.00        1.00           1        1.99900        1.00000
6 second sleep                                 6.00        0.00           1        6.00000        0.00000
(Other)                                        0.00        0.00           1        0.00000        0.00000
---------------------------------------  ----------  ----------  ----------  -------------  -------------
Total                                         11.00        1.00           4        2.74975        0.25000
---------------------------------------  ----------  ----------  ----------  -------------  -------------
[Timer timed (per call in ms): Elapsed: 0.00980, CPU: 0.00980]

Notes on Output

  • The two direct calls to the sleep procedure DBMS_Lock.Sleep consumed elapsed time of 3 and 6 seconds, as specified in the calls, but no CPU time
  • The insert statement consumed 2 seconds elapsed time, of which 1 second comes from CPU time, matching the field values, which the trigger uses to determine elapsed time and fraction of CPU time

Timer Set Custom Code Timing Feature Summary

We can summarise the features of Timer Set custom code timing in the following points:

  • Results are organised as tables of measures for lists of timers in one or more sets
  • Results are reported at the level of code section, and timing is aggregated between calls to API methods
  • Measures reported are elapsed times, numbers of calls, and CPU times
  • External program units may be included in the profiling: calls can be timed; internal profiling requires code changes
  • Profiling is performed, after initial setup, by means of instrumentation within the program units to be profiled, including an API call to return results

I applied my Timer_Set code timing package to some demo PL/SQL APIs in a Github module that also demonstrtates logging and unit testing. This is described here: Oracle PL/SQL API Demos Github Module






 

PL/SQL Profiling 3: Flat Profiler

Posted on by
Reply

This article describes the use of Oracle’s flat PL/SQL profiler (DBMS_PROFILER) on two example program structures. The examples are designed to illustrate its behaviour over as many different scenarios as possible, while keeping the examples as simple as possible. It’s based on an article published in March 2013 on the hierarchical profiler and updated shortly thereafter with the inclusion of Oracle’s older flat profiler and of custom code timing. In June 2020 installation and source code were put onto GitHub, and the article was restructured into an overview article with the detail on the three profiling methods as separate articles, of which this is the second. Here are links to the other three articles:

PL/SQL Profiling 1: Overview
PL/SQL Profiling 2: Hierarchical Profiler
PL/SQL Profiling 4: Custom Code Timing

All source code, including installation scripts, is available on GitHub:
GitHub: Oracle PL/SQL Profiling
Tweet with recording attached

Setup

The flat profiler setup and use is described in the Oracle document DBMS_PROFILER. The GitHub project linked to above includes scripts for setup of prerequisites such as grants and tables, and for installation of the custom code used for this demonstration. As described in the overview article, there are two example scripts profiled.

  • Example 1: General. This covers a wide range of scenarios
  • Example 2: Sleep. This covers the particular example of DBMS_Lock.Sleep

PL/SQL Flat Profiler: Data Model

Example 1: General

The example was descibed in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
PROMPT B1: Start profiling; A_Calls_B 
VAR RUN_ID NUMBER
DECLARE
  l_call_count       PLS_INTEGER := 0;
  l_result           PLS_INTEGER;
BEGIN

  l_result := DBMS_Profiler.Start_Profiler(
          run_comment => 'Profile for small test program with recursion',
          run_number  => :RUN_ID);

  Utils.W('Start: profile run id = ' || :RUN_ID);
  Prof_Test.A_Calls_B(l_call_count);

END;
/
PROMPT SQL: Static DB function call
SELECT Prof_Test.DBFunc
  FROM DUAL;

PROMPT B2: Static DB function; dynamic SQL; object constructor
DECLARE
  l_cur              SYS_REFCURSOR;
  l_ret_val          PLS_INTEGER;
  l_tab_count        Table_Count_Type;

BEGIN

  SELECT Prof_Test.DBFunc
    INTO l_ret_val
    FROM DUAL;

  OPEN l_cur FOR 'SELECT Count(*) FROM all_tab_columns'; 
  FETCH l_cur INTO l_ret_val; 
  CLOSE l_cur;

  l_tab_count := Table_Count_Type('EMP');

END;
/
PROMPT B3: R_Calls_R; stop profiling
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  Prof_Test.R_Calls_R(l_call_count);

  Utils.W('Stop: result = ' || DBMS_Profiler.Stop_Profiler);
  
END;
/
SET TIMING OFF
@dprof_queries :RUN_ID

The script is structured as an anonymous block, B1, then a stand-alone SQL query, followed by two more anonymous blocks, B2 and B3. Profiling is started by a call to DBMS_Profiler.Start_Profiler in the first block.

The last block stops the profiling. The custom queries are run at the end from the script dprof_queries.sql, passing in the run identifier that’s been saved in a bind variable.

Results for Example 1: General

The results in this section come from the script dprof_queries.sql that queries the tables populated by the profiler.

Example 1: General – Run Header

The record produced in the run table, PLSQL_PROFILER_RUNS, was:

 Run Id Time     Seconds  Microsecs
------- -------- ------- ----------
      1 07:52:12   0.766     766000

Example 1: General – Profiler Data Summaries

Profiler data overall summary (PLSQL_PROFILER_DATA):

Seconds  Microsecs    Calls
------- ---------- --------
  0.731     730945       70

Profiler data summary by unit (PLSQL_PROFILER_DATA):

Unit                 Unit# Seconds  Microsecs    Calls
-------------------- ----- ------- ---------- --------
<anonymous>              1   0.000         47        3
<anonymous>              3   0.000         63        2
<anonymous>              4   0.000        103        2
<anonymous>              5   0.402     401821        6
<anonymous>              7   0.000        103        2
<anonymous>              8   0.000         87        3
PROF_TEST                2   0.309     308722       48
TABLE_COUNT_TYPE         6   0.020      20000        4

Example 1: General – Profiler Data by Unit

The records produced in the functions table, PLSQL_PROFILER_DATA, are listed below in order of unit name, then unit number and line number. The table is joined to PLSQL_PROFILER_UNITS to get the unit name and other details, which are then used to outer-join to the system view ALL_SOURCE to get the line of source code for stored units (i.e. not for anonymous blocks).

Seconds  Microsecs   Min S   Max S    Calls Unit                 Unit# Type            Line# Line Text
------- ---------- ------- ------- -------- -------------------- ----- --------------- ----- ------------------------------------------------------------------
  0.000          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     1
  0.000          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     2
  0.000          2   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     6
  0.000         26   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    10
  0.000         18   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    11
  0.000          1   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    13
  0.000         63   0.000   0.000        2 <anonymous>              3 ANONYMOUS BLOCK     1
  0.000        103   0.000   0.000        2 <anonymous>              4 ANONYMOUS BLOCK     1
  0.000          8   0.000   0.000        0 <anonymous>              5 ANONYMOUS BLOCK     1
  0.000        139   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK     8
  0.151     150687   0.151   0.151        1 <anonymous>              5 ANONYMOUS BLOCK    12
  0.251     250899   0.251   0.251        1 <anonymous>              5 ANONYMOUS BLOCK    13
  0.000         30   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK    14
  0.000         55   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK    16
  0.000          3   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK    18
  0.000        103   0.000   0.000        2 <anonymous>              7 ANONYMOUS BLOCK     1
  0.000          4   0.000   0.000        0 <anonymous>              8 ANONYMOUS BLOCK     1
  0.000          0   0.000   0.000        1 <anonymous>              8 ANONYMOUS BLOCK     2
  0.000         44   0.000   0.000        1 <anonymous>              8 ANONYMOUS BLOCK     5
  0.000         39   0.000   0.000        1 <anonymous>              8 ANONYMOUS BLOCK     7
  0.000          0   0.000   0.000        0 <anonymous>              8 ANONYMOUS BLOCK     9
  0.000          1   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY        1 PACKAGE BODY Prof_Test AS
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY       44 g_num NUMBER := 0;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY       71 PROCEDURE A_Calls_B(
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       75 x_call_no := x_call_no + 1;
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       76 PRAGMA INLINE (Rest_a_While, 'YES');
  0.017      16691   0.004   0.013        2 PROF_TEST                2 PACKAGE BODY       77 Rest_a_While(1000 * x_call_no);
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       79 PRAGMA INLINE (Rest_a_While, 'YES'); -- Both pragmas are required
  0.034      33515   0.009   0.025        2 PROF_TEST                2 PACKAGE BODY       80 Rest_a_While(2000 * x_call_no);
  0.000          1   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       82 IF x_call_no < 4 THEN
  0.000          1   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       83 B_Calls_A(x_call_no);
  0.000          2   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       86 END A_Calls_B;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY       94 PROCEDURE B_Calls_A(
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       98 x_call_no := x_call_no + 1;
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       99 PRAGMA INLINE (Rest_a_While, 'YES');
  0.126     126418   0.044   0.083        2 PROF_TEST                2 PACKAGE BODY      100 Rest_a_While(5000 * x_call_no);
  0.000          1   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      102 IF x_call_no < 4 THEN
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      103 A_Calls_B(x_call_no);
  0.000          1   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      106 END B_Calls_A;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY      114 PROCEDURE R_Calls_R(
  0.000         40   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      118 DBMS_Output.Put_Line('In R_Calls_R, x_call_no = ' || x_call_no);
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      119 x_call_no := x_call_no + 1;
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      120 PRAGMA INLINE (Rest_a_While, 'YES');
  0.041      40688   0.015   0.026        2 PROF_TEST                2 PACKAGE BODY      121 Rest_a_While(3000 * x_call_no);
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      123 IF x_call_no < 2 THEN
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      124 R_Calls_R(x_call_no);
  0.000          2   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      127 END R_Calls_R;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY      134 FUNCTION DBFunc
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      138 PRAGMA INLINE (Rest_a_While, 'YES');
  0.091      91346   0.042   0.049        2 PROF_TEST                2 PACKAGE BODY      139 Rest_a_While(10000);
  0.000          2   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      141 RETURN 99;
  0.000          2   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      143 END DBFunc;
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      145 END Prof_Test;
  0.000          3   0.000   0.000        0 TABLE_COUNT_TYPE         6 TYPE BODY          50 CONSTRUCTOR FUNCTION Table_Count_Type(
  0.000          1   0.000   0.000        1 TABLE_COUNT_TYPE         6 TYPE BODY          54 SELF.search_str := p_search_str;
  0.020      19991   0.020   0.020        1 TABLE_COUNT_TYPE         6 TYPE BODY          55 SELECT Count(*)
  0.000          3   0.000   0.000        1 TABLE_COUNT_TYPE         6 TYPE BODY          60 RETURN;
  0.000          2   0.000   0.000        1 TABLE_COUNT_TYPE         6 TYPE BODY          62 END;

58 rows selected.

Notes on Output

The manual has notes on interpreting output, DBMS_PROFILER Operational Notes, and we can add some notes here on the output above.

Unit Names and Numbers

Unit numbers appear to be consecutive integers generated at run time in the order in which the units are encountered. Unit names for saved source code units such as packages and types are the names of the stored units. Anonymous blocks of PL/SQL are not stored as saved units and so do not have their own names, and are assigned the name <anonymous>, but separate top-level blocks have distinct unit numbers.

Named Units and Source Lines

Named units such as package and type bodies have source code lines accessible in the system view ALL_SOURCE, and these are displayed in the output above. See the query section below for the join code.

Anonymous Blocks

We can't include the source text for anonymous blocks as it is not stored in the database. However, we can generally work out which unit numbers correspond to which blocks manually, and then use the line numbers to identify the corresponding source lines, with the line numbers being counted from the first line in the block as line 1. For example, line 11 in the output above for unit 1 used about 1ms and can be seen to correspond to the 11'th line in the block labelled B1 in the driver script:

  Prof_Test.A_Calls_B(l_call_count);
PRAGMA INLINE

Calls to the Rest_a_While procedure in package Prof_Test are preceded by the inline pragma that causes the procedure code to be inlined by the PL/SQL engine. In this case we do not see any references to lines numbers 49-59 in Prof_Test where the procedure is located, only to the calling statements on lines 75, 78, 98, 119 and 137.

Example 2: Sleep

The example was descibed in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
VAR RUN_ID NUMBER
PROMPT B1: Start profiling; DBMS_Lock.Sleep, 3 + 6; stop profiling
DECLARE
  l_result           PLS_INTEGER;
BEGIN

  l_result := DBMS_Profiler.Start_Profiler(
          run_comment => 'Profile for DBMS_Lock.Sleep example',
          run_number  => :RUN_ID);

  Utils.W('Start: profile run id = ' || :RUN_ID);

  DBMS_Lock.Sleep(3);

  INSERT INTO trigger_tab VALUES (2, 0.5);

  DBMS_Lock.Sleep(6);

  Utils.W('Stop: result = ' || DBMS_Profiler.Stop_Profiler);

END;
/
SET TIMING OFF
@dprof_queries :RUN_ID

The script runs the start profiling procedure, then makes calls to a system procedure, DBMS_Lock.Sleep, which sleeps without using CPU time, then inserts to a table with a Before Insert trigger that calls a custom sleep procedure, Utils.Sleep, and finally calls a custom utility that stops the profiling and analyses the trace file created. Utils.Sleep itself calls DBMS_Lock.Sleep to do non-CPU sleeping and also runs a mathematical operation in a loop to use CPU time. The custom queries are run at the end from the script hprof_queries.sql, passing in the run identifier that's been saved in a bind variable.

Results for Example 2: Sleep

The results in this section come from the script dprof_queries.sql that queries the tables populated by the profiler.

This second example was added after I came across an AskTom post concerning a discrepancy between reported times at the aggregate level and detail levels for the flat profiler. I posted a suggestion that using the hierarchical profiler might resolve the problem Try the hierarchical profiler..., and then added this second example to my original article in 2013 (since extended).

Example 2: Sleep - Run Header

The record produced in the run table, PLSQL_PROFILER_RUNS, was:

 Run Id Time     Seconds  Microsecs
------- -------- ------- ----------
      2 07:52:22  11.000   11000000

Example 2: Sleep - Profiler Data Summaries

Profiler data overall summary (PLSQL_PROFILER_DATA):

Seconds  Microsecs    Calls
------- ---------- --------
  0.000        265        7

Profiler data summary by unit (PLSQL_PROFILER_DATA):

Unit                 Unit# Seconds  Microsecs    Calls
-------------------- ----- ------- ---------- --------
<anonymous>              1   0.000        242        5
SLEEP_BI                 2   0.000         23        2

Example 2: Sleep - Profiler Data by Unit and Line

The records produced in the functions table, PLSQL_PROFILER_DATA, are listed below in order of unit name, then unit number and line number. 

Seconds  Microsecs   Min S   Max S    Calls Unit                 Unit# Type            Line# Line Text
------- ---------- ------- ------- -------- -------------------- ----- --------------- ----- ------------------------------------------------------------------
  0.000          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     1
  0.000          2   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     5
  0.000         23   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK     9
  0.000         10   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    11
  0.000        199   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    13
  0.000          3   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    15
  0.000          5   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    17
  0.000          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK    19
  0.000          2   0.000   0.000        0 SLEEP_BI                 2 TRIGGER             1 TRIGGER sleep_bi
  0.000         20   0.000   0.000        1 SLEEP_BI                 2 TRIGGER             2 BEFORE INSERT
  0.000          1   0.000   0.000        1 SLEEP_BI                 2 TRIGGER             4 FOR EACH ROW

11 rows selected.

Notes on Output

Calls to Units with EXECUTE ONLY Access

The manual states "you cannot use the package to profile units for which EXECUTE ONLY access has been granted". In this example there are calls to two units where this applies: the system package DBMS_Lock, and the custom utility package Utils, which is in a different schema (lib) from the one (app) in which the script is run.

In the output above we can see the lines from which the calls are made but nothing within the units called.

Aggregate/Detail Timing Discrepancy

As was noted in the AskTom thread referenced above, where the flat profiler does not provide data for program units, such as DBMS_Lock.Sleep, the timings at the detail level do not add up to the overall time recorded in the runs table. As there were three calls using elapsed time of 11 seconds in total the total recorded in the runs table is 11 seconds, while this 11 seconds is missing from the detail records, which add up to only 265 microseconds in total.

Queries

The queries are in the script dprof_queries.sql. All queries are for a given RUNID, passed in as a sqlplus parameter.

Run Header Query

SELECT runid,
       To_Char(run_date, 'hh24:mi:ss') run_date,
       Round(run_total_time/1000000000, 3) seconds,
       Round(run_total_time/1000, 0)  micro_s
  FROM plsql_profiler_runs
 WHERE runid = &RUN_ID
  • RUN_TOTAL_TIME in nanoseconds is converted to seconds and microseconds

Profiler Data Overall Summary Query

SELECT Round(Sum(dat.total_time/1000000000), 3) seconds,
       Round(Sum(dat.total_time/1000), 0)  micro_s,
       Sum(dat.total_occur) calls
  FROM plsql_profiler_data dat
 WHERE dat.runid = &RUN_ID
  • This query sums the times and calls in PLSQL_PROFILER_DATA for the given RUNID

Profiler Data Summary by Unit Query

SELECT unt.unit_name,
       dat.unit_number,
       Round(Sum(dat.total_time/1000000000), 3) seconds,
       Round(Sum(dat.total_time/1000), 0)  micro_s,
       Sum(dat.total_occur) calls
  FROM plsql_profiler_data dat
  JOIN plsql_profiler_units unt
    ON unt.runid = dat.runid
   AND unt.unit_number = dat.unit_number
 WHERE dat.runid = &RUN_ID
 GROUP BY unt.unit_name,
          dat.unit_number
 ORDER BY 1, 2, 3
  • This query sums the times and calls in PLSQL_PROFILER_DATA by unit name and number, for the given RUNID

Lines Query

SELECT Round(dat.total_time/1000000000, 3) seconds,
       Round(dat.total_time/1000, 0)  micro_s,
       Round(dat.min_time/1000000000, 3) min_secs,
       Round(dat.max_time/1000000000, 3) max_secs,
       dat.total_occur calls,
       unt.unit_name,
       dat.unit_number,
       unt.unit_type,
       dat.line#,
       Trim(src.text) text
  FROM plsql_profiler_data dat
  JOIN plsql_profiler_units unt
    ON unt.runid            = dat.runid
   AND unt.unit_number      = dat.unit_number
  LEFT JOIN all_source      src
    ON src.type             != 'ANONYMOUS BLOCK'
   AND src.name             = unt.unit_name 
   AND src.line             = dat.line#
   AND src.owner            = unt.unit_owner
   AND src.type             = unt.unit_type
 WHERE dat.runid            = &RUN_ID
 ORDER BY unt.unit_name, unt.unit_number, dat.line#
  • This query lists the times and calls in PLSQL_PROFILER_DATA, for the given RUNID
  • PLSQL_PROFILER_UNITS is joined on UNIT_NUMBER
  • The view ALL_SOURCE is outer-joined on UNIT_NAME, UNIT_OWNER, UNIT_TYPE, LINE# to give the source line for stored source
  • Anonymous blocks do not have any saved source lines

Flat Profiler Feature Summary

We can summarise the features of the Flat Profiler in the following points:

  • Results are organised as lists of measures by line
  • Results are reported at the line level
  • Measures reported are elapsed times and numbers of calls, but not CPU times
  • External program units may not be included in the profiling (they are included only if the user can debug the unit)
  • Profiling is performed, after initial setup, by means of before and after API calls, followed by querying of results in tables