Shortest Path Analysis of Large Networks by SQL and PL/SQL – Intro

This is an introduction to an article, Shortest Path Analysis of Large Networks by SQL and PL/SQL, on the use of SQL and PL/SQL to solve shortest path network problems on an Oracle database. It provides solutions in pure SQL (based on previous articles by the author), and solutions in PL/SQL with embedded SQL that scale better for larger problems.

It applies the solutions to a range of problems, upto a size of 2,800,309 nodes and 109,262,592 links.

Standard and custom methods for execution time profiling of the code are included, and one of the algorithms implemented in PL/SQL is tuned based on the profiling.

The two PL/SQL entry points have automated unit tests using the Math Function Unit Testing design pattern, Trapit – Oracle PL/SQL unit testing module.


Movie Morsel: Six Degrees of Kevin Bacon

All code and examples are available on GitHub.

There is a series of mp4 recordings, in the mp4 folder on GitHub, briefly going through the sections of the blog post, which can also be viewed via Twitter:

Twitter Recordings

Contents

The contents of the article are listed below.






SQL for Period Aggregate Reporting

[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 2: Hierarchical Profiler

This article describes the use of Oracle’s hierarchical PL/SQL profiler (DBMS_HProf) 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 first. Here are links to the other three articles:

PL/SQL Profiling 1: Overview
PL/SQL Profiling 3: Flat 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 hierarchical profiler setup and use is described in the Oracle document Using the PL/SQL Hierarchical 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 Hierarchical 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 
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  HProf_Utils.Start_Profiling;
  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
VAR RUN_ID NUMBER
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  Prof_Test.R_Calls_R(l_call_count);

  :RUN_ID := HProf_Utils.Stop_Profiling(
    p_run_comment => 'Profile for small test program with recursion',
    p_filename    => 'hp_example_general.html');
  Utils.W('Run id is ' || :RUN_ID);
END;
/
SET TIMING OFF
@hprof_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 includes a call to a custom utility, HProf_Utils.Stop_Profiling, that stops the profiling and analyses the trace file created in two ways:

  • Writing a (standard) HTML report on the results using a DBMS_HProf call
  • Writing the results to standard tables created during installation using a DBMS_HProf call

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 1: General

The results in this section come from the script hprof_queries.sql that queries the tables populated by the analyse step.

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

 Run Id Run Time                      Microsecs Seconds Comment
------- ---------------------------- ---------- ------- ------------------------------------------------------------
     12 02-JUN-20 06.30.37.128000 AM     823833   0.820 Profile for small test program with recursion

The records produced in the functions table, DBMSHP_FUNCTION_INFO, were:

Owner Module            Sy Function                  Line# Subtree MicroS Function MicroS Calls
----- ---------------- --- ------------------------- ----- -------------- --------------- -----
APP   HPROF_UTILS        4 STOP_PROFILING               61             26              26     1
APP   PROF_TEST          5 A_CALLS_B                    71         128199            9631     1
APP   PROF_TEST          6 A_CALLS_B@1                  71          87951           27332     1
APP   PROF_TEST          7 B_CALLS_A                    63         118568           30617     1
APP   PROF_TEST          8 B_CALLS_A@1                  63          60619           60619     1
APP   PROF_TEST          9 DBFUNC                      134          62114           62114     2
APP   PROF_TEST         10 R_CALLS_R                   114          27684            9234     1
APP   PROF_TEST         11 R_CALLS_R@1                 114          18428           18426     1
APP   PROF_TEST         12 __pkg_init                    0              3               3     1
APP   TABLE_COUNT_TYPE  13 TABLE_COUNT_TYPE             50         521332              31     1
APP   TABLE_COUNT_TYPE  22 __static_sql_exec_line55     55         521301          521301     1
SYS   DBMS_HPROF        14 STOP_PROFILING              747              0               0     1
SYS   DBMS_HPROF        23 __static_sql_exec_line700   700             67              67     1
SYS   DBMS_OUTPUT       15 GET_LINES                   180             79              79     3
SYS   DBMS_OUTPUT       16 NEW_LINE                    117              0               0     2
SYS   DBMS_OUTPUT       17 PUT                          77             23              23     2
SYS   DBMS_OUTPUT       18 PUT_LINE                    109             24               1     2
                         1 __anonymous_block             0        1818326             590     5
                         2 __plsql_vm                    0        1848468              17     6
                         3 __plsql_vm@1                  0          31993               4     1
                        19 __dyn_sql_exec_line12        12         133537          133537     1
                        20 __sql_fetch_line13           13        1100678         1100678     1
                        21 __static_sql_exec_line8       8          34400            2407     1

23 rows selected.

The “Subtree MicroS” and “Function MicroS” values are the total times in microseconds for the subtree including function, and function-only processing, respectively.

In the “Function” column, as well as procedure and function names in upper case, there are a number of names with a prefix “__”. The meanings of these are outlined in a table in the Oracle document mentioned above and reproduced below:


Notice that some of the function names have a suffix “@1”. These correspond to recursive calls, as will be clear from the network diagram later.

The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, (with joins to DBMSHP_FUNCTION_INFO to get parent and child function details) were:

Parent: Module            Sy Function                       Child:  Module            Sy Function                       Subtree MicroS Function MicroS Calls
------- ---------------- --- ------------------------------ ------- ---------------- --- ------------------------------ -------------- --------------- -----
APP     HPROF_UTILS        4 STOP_PROFILING                 SYS     DBMS_HPROF        14 STOP_PROFILING                              0               0     1
APP     PROF_TEST          5 A_CALLS_B                      APP     PROF_TEST          7 B_CALLS_A                              118568           30617     1
APP     PROF_TEST          7 B_CALLS_A                      APP     PROF_TEST          6 A_CALLS_B@1                             87951           27332     1
APP     PROF_TEST         11 R_CALLS_R@1                    SYS     DBMS_OUTPUT       18 PUT_LINE                                    2               0     1
APP     PROF_TEST          6 A_CALLS_B@1                    APP     PROF_TEST          8 B_CALLS_A@1                             60619           60619     1
APP     PROF_TEST         10 R_CALLS_R                      APP     PROF_TEST         11 R_CALLS_R@1                             18428           18426     1
APP     PROF_TEST         10 R_CALLS_R                      SYS     DBMS_OUTPUT       18 PUT_LINE                                   22               1     1
APP     TABLE_COUNT_TYPE  13 TABLE_COUNT_TYPE               APP     TABLE_COUNT_TYPE  22 __static_sql_exec_line55               521301          521301     1
SYS     DBMS_OUTPUT       18 PUT_LINE                       SYS     DBMS_OUTPUT       17 PUT                                        23              23     2
SYS     DBMS_OUTPUT       18 PUT_LINE                       SYS     DBMS_OUTPUT       16 NEW_LINE                                    0               0     2
                           1 __anonymous_block                                        21 __static_sql_exec_line8                 34400            2407     1
                           1 __anonymous_block                                        20 __sql_fetch_line13                    1100678         1100678     1
                           1 __anonymous_block                                        19 __dyn_sql_exec_line12                  133537          133537     1
                           1 __anonymous_block              SYS     DBMS_OUTPUT       15 GET_LINES                                  79              79     3
                           1 __anonymous_block              APP     TABLE_COUNT_TYPE  13 TABLE_COUNT_TYPE                       521332              31     1
                           1 __anonymous_block              APP     PROF_TEST         10 R_CALLS_R                               27684            9234     1
                           3 __plsql_vm@1                   APP     PROF_TEST          9 DBFUNC                                  31989           31989     1
                           2 __plsql_vm                     APP     PROF_TEST          9 DBFUNC                                  30125           30125     1
                           1 __anonymous_block              APP     HPROF_UTILS        4 STOP_PROFILING                             26              26     1
                           2 __plsql_vm                                                1 __anonymous_block                     1818326             590     5
                          21 __static_sql_exec_line8                                   3 __plsql_vm@1                            31993               4     1

21 rows selected.

The “Subtree MicroS” and “Function MicroS” values are the total times in microseconds for the subtree including function, and function-only processing, respectively, for the child function while called from all instances of the parent.

Network Diagrams for Example 1: General

The DBMSHP_PARENT_CHILD_INFO holds parent-child links between functions, while the function detail information is held in DBMSHP_FUNCTION_INFO. The following three columns occur in both tables (descriptions from the Oracle doc):

  • SUBTREE_ELAPSED_TIME – Elapsed time, in microseconds, for subprogram, including time spent in descendant subprograms
  • FUNCTION_ELAPSED_TIME – Elapsed time, in microseconds, for subprogram, excluding time spent in descendant subprograms
  • CALLS – Number of calls to subprogram

In the DBMSHP_FUNCTION_INFO they are aggregates for the subprogram overall, whereas in the DBMSHP_PARENT_CHILD_INFO they are aggregates for the subprogram when called from its parent.

The data in the tables represent a directed network (or ‘digraph’) of nodes and links. A root node is defined as a node that has no parent node, and we may have isolated root nodes that do not appear in the links table. It can sometimes be useful when querying network data to add a dummy node as a parent of all the root nodes, creating a single root for the network and ensuring all the non-dummy nodes appear as child nodes in the adjusted links set. Here is a diagram of the adjusted network for this example, with just the links and the function numbers included:


Notice that there are four (real) root nodes, two of which are isolated. Notice also that there are two loops in the network, whereby nodes (functions) 9 and 18 can be reached by two different paths each. However, there are no cycles since no node is both ancestor and descendant of another.

We can display more of the information the HProf utility produces in extended versions of the network diagram, where we’ll separate the network into its four subnetworks, shown in two diagrams.


This diagram, of the first subnetwork, has the function names and shows the total elapsed times used by the functions within the nodes, and the elapsed times used by the functions when called by their parents within the links.

Loops and Hierarchies

The diagram shows two loops, where there are two routes between the loop start and end points, indicated by different colours. The second loop has two child nodes coming from the end point, and hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links to them to be duplicated. We’ll see how to filter out the duplicates in the queries section below.


This diagram is for the other three subnetworks.

Network Query Output for Example 1: General

Function tree                   Sy Owner Module           Inst.  Subtree MicroS Function MicroS Calls Row
------------------------------ --- ----- ---------------- ------ -------------- --------------- ----- ---
__plsql_vm                       2                                      1848468              17     6   1
  __anonymous_block              1                                      1818326             590     5   2
    __sql_fetch_line13          20                                      1100678         1100678     1   3
    TABLE_COUNT_TYPE            13 APP   TABLE_COUNT_TYPE                521332              31     1   4
      __static_sql_exec_line55  22 APP   TABLE_COUNT_TYPE                521301          521301     1   5
    __dyn_sql_exec_line12       19                                       133537          133537     1   6
    __static_sql_exec_line8     21                                        34400            2407     1   7
      __plsql_vm@1               3                                        31993               4     1   8
        DBFUNC                   9 APP   PROF_TEST        1 of 2          31989           31989     1   9
    R_CALLS_R                   10 APP   PROF_TEST                        27684            9234     1  10
      R_CALLS_R@1               11 APP   PROF_TEST                        18428           18426     1  11
        PUT_LINE                18 SYS   DBMS_OUTPUT      1 of 2              2               0     1  12
          PUT                   17 SYS   DBMS_OUTPUT      1 of 2             23              23     2  13
          NEW_LINE              16 SYS   DBMS_OUTPUT      1 of 2              0               0     2  14
      PUT_LINE                  18 SYS   DBMS_OUTPUT      2 of 2             22               1     1  15
    GET_LINES                   15 SYS   DBMS_OUTPUT                         79              79     3  18
    STOP_PROFILING               4 APP   HPROF_UTILS                         26              26     1  19
      STOP_PROFILING            14 SYS   DBMS_HPROF                           0               0     1  20
  DBFUNC                         9 APP   PROF_TEST        2 of 2          30125           30125     1  21
A_CALLS_B                        5 APP   PROF_TEST                       128199            9631     1  22
  B_CALLS_A                      7 APP   PROF_TEST                       118568           30617     1  23
    A_CALLS_B@1                  6 APP   PROF_TEST                        87951           27332     1  24
      B_CALLS_A@1                8 APP   PROF_TEST                        60619           60619     1  25
__static_sql_exec_line700       23 SYS   DBMS_HPROF                          67              67     1  26
__pkg_init                      12 APP   PROF_TEST                            3               3     1  27

25 rows selected.

The report query script hprof_queries.sql queries the network in two ways, using Oracle’s proprietary Connect By syntax, and also using the ANSI standard recursive subquery factoring. The output above comes from the recursive subquery factoring query. The query code is discussed in a later section.

Notes on Output

Recursive Calls – “@1” Suffix

The hierarchical profiler appends a suffix “@1” on to functions called recursively, as in A_CALLS_B@1 and B_CALLS_A@1 which is an example of mutual recursion between A_CALLS_B and B_CALLS_A.

Anonymous Block (__anonymous_block)

This function corresponds to invocations of anonymous blocks, obviously enough. However, there is an apparent anomaly in the number of calls listed, 5, because the driving program has only three such blocks, and there are none in the called PL/SQL code. I would surmise that the apparent discrepancy arises from the enabling of SERVEROUTPUT, which appears to result in a secondary block being associated with each explicit SQL*Plus block, that issues a call to GET_LINES to process buffered output.

PL/SQL Engine (__plsql_vm)

This function corresponds to external invocations of PL/SQL such as from a SQL*Plus session. There are 6 calls, 5 of them presumably being linked with the external anonymous blocks, and the 6’th with DBFUNC, where a PL/SQL function is called from a SQL statement from SQL*Plus.

Notice that the SQL statement calling a database function from within PL/SQL generates the recursive call to the engine, __plsql_vm@1

Package Initialization (__pkg_init)

The Prof_Test package has a package variable g_num that is initialized to 0 on first invocation, which gives rise to the __pkg_init function in the output.

Second Root (A_CALLS_B)

The above function does not have the __plsql_vm/__anonymous_block ancestry that might be expected because profiling only started within the enclosing block.

Inlined Procedure (Rest_a_While)

I wrote a small procedure, Rest_a_While, to generate some elapsed time in the recursive procedures, but preceded it with the INLINE pragma, an optimization feature new in 11g. This had the desired effect of removing the calls from the profiling output and including the times in the calling procedures. Rest_a_While does not make the obvious call to DBMS_Lock.Sleep because that procedure cannot be inlined. subprogram inlining in 11g provides some analysis of the inlining feature.

Link Duplication

As mentioned earlier, hierarchical queries cause links to be duplicated below any loops, as the queries follow all paths. However, in the output above we have a single record for each of the links, including the additional root node dummy links. This is achieved by filtering out the duplicates in an additional subquery. The “Inst.” column lists the instance number of a function having more than one instance, and the children of any such function are only listed once with the gaps in the “Row” column indicating where duplicates have been suppressed (rows 13 and 14 are omitted here).

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
BEGIN

  HProf_Utils.Start_Profiling;
  DBMS_Lock.Sleep(3);

  DBMS_Lock.Sleep(6);

  :RUN_ID := HProf_Utils.Stop_Profiling(
    p_run_comment => 'Profile for DBMS_Lock.Sleep',
    p_filename    => 'hp_example_sleep.html');
  Utils.W('Run id is ' || :RUN_ID);
END;
/
SET TIMING OFF
@hprof_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 trace file is analysed in two ways:

  • Writing a (standard) HTML report on the results using a DBMS_HProf call
  • Writing the results to standard tables created during installation using a DBMS_HProf call

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 hprof_queries.sql that queries the tables populated by the analyse step.

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

 Run Id Run Time                      Microsecs Seconds Comment
------- ---------------------------- ---------- ------- ------------------------------------------------------------
     22 18-JUN-20 12.49.56.816000 PM   10997855  11.000 Profile for DBMS_Lock.Sleep

The records produced in the functions table, DBMSHP_FUNCTION_INFO, were:

Owner Module            Sy Function                  Line# Subtree MicroS Function MicroS Calls
----- ---------------- --- ------------------------- ----- -------------- --------------- -----
APP   HPROF_UTILS        2 STOP_PROFILING               61             87              87     1
APP   SLEEP_BI           3 SLEEP_BI                      0        1999602             327     1
LIB   UTILS              4 SLEEP                       351        1999268          999837     1
LIB   UTILS              5 __pkg_init                    0              2               2     1
LIB   UTILS              6 __pkg_init                    0              5               5     1
SYS   DBMS_HPROF         7 STOP_PROFILING              747              0               0     1
SYS   DBMS_HPROF        11 __static_sql_exec_line700   700             77              77     1
SYS   DBMS_LOCK          8 SLEEP                       207        9997626         9997626     3
SYS   DBMS_LOCK          9 __pkg_init                    0              3               3     1
                         1 __plsql_vm                    0        1999606               4     1
                        10 __static_sql_exec_line6       6        2005266            5660     1

11 rows selected.

The “Subtree MicroS” and “Function MicroS” values are the total times in microseconds for the subtree including function, and function-only processing, respectively.

The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, (with joins to DBMSHP_FUNCTION_INFO to get parent and child function details) were:

Parent: Module            Sy Function                       Child:  Module            Sy Function                       Subtree MicroS Function MicroS Calls
------- ---------------- --- ------------------------------ ------- ---------------- --- ------------------------------ -------------- --------------- -----
APP     HPROF_UTILS        2 STOP_PROFILING                 SYS     DBMS_HPROF         7 STOP_PROFILING                              0               0     1
APP     SLEEP_BI           3 SLEEP_BI                       LIB     UTILS              5 __pkg_init                                  2               2     1
APP     SLEEP_BI           3 SLEEP_BI                       LIB     UTILS              6 __pkg_init                                  5               5     1
APP     SLEEP_BI           3 SLEEP_BI                       LIB     UTILS              4 SLEEP                                 1999268          999837     1
LIB     UTILS              4 SLEEP                          SYS     DBMS_LOCK          8 SLEEP                                  999431          999431     1
                          10 __static_sql_exec_line6                                   1 __plsql_vm                            1999606               4     1
                           1 __plsql_vm                     APP     SLEEP_BI           3 SLEEP_BI                              1999602             327     1

7 rows selected.

The “Subtree MicroS” and “Function MicroS” values are the total times in microseconds for the subtree including function, and function-only processing, respectively, for the child function while called from all instances of the parent.

Network Diagrams for Example 2: Sleep



The network diagram shows 5 nodes appearing as (real) roots, of which one (8) is also linked as a child.


The extended network diagram with function names and times included shows 9 seconds of time used by the SLEEP function in two root-level calls
and 1 second in a third call as the child of the custom Utils Sleep function.

Network Query Output for Example 2: Sleep

Function tree                   Sy Owner Module           Inst.  Subtree MicroS Function MicroS Calls Row
------------------------------ --- ----- ---------------- ------ -------------- --------------- ----- ---
SLEEP                            8 SYS   DBMS_LOCK        1 of 2        8998195         8998195     2   1
__static_sql_exec_line6         10                                      2005266            5660     1   2
  __plsql_vm                     1                                      1999606               4     1   3
    SLEEP_BI                     3 APP   SLEEP_BI                       1999602             327     1   4
      SLEEP                      4 LIB   UTILS                          1999268          999837     1   5
        SLEEP                    8 SYS   DBMS_LOCK        2 of 2         999431          999431     1   6
      __pkg_init                 6 LIB   UTILS                                5               5     1   7
      __pkg_init                 5 LIB   UTILS                                2               2     1   8
STOP_PROFILING                   2 APP   HPROF_UTILS                         87              87     1   9
  STOP_PROFILING                 7 SYS   DBMS_HPROF                           0               0     1  10
__static_sql_exec_line700       11 SYS   DBMS_HPROF                          77              77     1  11
__pkg_init                       9 SYS   DBMS_LOCK                            3               3     1  12

12 rows selected.

Oracle HProf HTML Reports

A standard HTML report can be produced after the profiling is stopped, by a call to one of the Analyze methods. The custom procedure below calls this method to write the report to a CLOB field, then calls DBMS_XSLProcessor.CLOB2File to write the contents to file.

The second Analyze call populates the tables read by the custom queries.

FUNCTION Stop_Profiling(
            p_run_comment                  VARCHAR2,                       -- run comment
            p_filename                     VARCHAR2) RETURN PLS_INTEGER IS -- file name for html report
  l_report_clob   CLOB;
BEGIN

  DBMS_HProf.Stop_Profiling;
  DBMS_HProf.Analyze(trace_id => g_trace_id, report_clob => l_report_clob);
  DBMS_XSLProcessor.CLOB2File(cl => l_report_clob, flocation => 'INPUT_DIR', fname => p_filename);
  RETURN DBMS_HProf.Analyze(trace_id => g_trace_id, run_comment => p_run_comment);

END Stop_Profiling;

The driver scripts specify the file name hp_example_general.html and hp_example_sleep.html, and these are written to the folder in the Oracle directory INPUT_DIR. The files for the examples are included in the associated GitHub project. The report starts with a list of the included subreports, as in the screenshot below:


Here is a screenshot for the first of the subreports for the general example:

Network Queries

The queries are in the script hprof_queries.sql, and we discuss the network queries in this section. The script also contains simple queries against the base tables. All queries are for a given RUNID, passed in as a sqlplus parameter.

Connect By Query

WITH links (node_fr, node_to, owner, module, function, sub_t, fun_t, calls) AS (
    SELECT  0, fni.symbolid, fni.owner, fni.module, fni.function, fni.subtree_elapsed_time, fni.function_elapsed_time, fni.calls
      FROM dbmshp_function_info fni
     WHERE fni.runid = &RUN_ID
       AND NOT EXISTS (SELECT 1 FROM dbmshp_parent_child_info pci WHERE pci.childsymid = fni.symbolid AND pci.runid = fni.runid)
     UNION ALL
    SELECT pci.parentsymid,
           pci.childsymid,
           fi.owner,
           fi.module ,
           fi.function,
           pci.subtree_elapsed_time,
           pci.function_elapsed_time,
           pci.calls
      FROM dbmshp_parent_child_info  pci
      JOIN dbmshp_function_info      fi 
        ON pci.runid                 = fi.runid 
       AND pci.childsymid            = fi.symbolid
     WHERE pci.runid                 = &RUN_ID
)
SELECT RPAD(' ', (LEVEL-1)*2, ' ') || function ftree,
       node_to sy,
       owner,
       module,
       sub_t,
       fun_t,
       calls
  FROM links
CONNECT BY PRIOR node_to = node_fr
START WITH node_fr = 0
ORDER SIBLINGS BY sub_t DESC, fun_t DESC, calls DESC, node_to

Notes on Connect By Query

Links Subquery

In the basic network diagrams we added a dummy root node so that all real nodes appear as child nodes, and this is implemented in the links subquery here as a union between new links to the real root nodes and the original links. This allows the main query connecting the revised links set to cover all nodes.

Sibling Ordering

The ORDER SIBLINGS BY clause allows us to order sibling nodes by subtree elapsed time descending, with additional tie-break columns.

Link Duplication

The network for the first example has two loops, and the second loop has two child nodes coming from the end point. Hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links below the loop to be duplicated as all paths are followed. This is seen in the output below for the first example, with 28 rows compared with 26 rows for the output displayed earlier, using a query with filtering implemented. The query can be extended to filter out the duplicates using analytic functions, as is implemented for the recursive subquery factoring query.

Function tree                   Sy Owner Module           Subtree MicroS Function MicroS Calls
------------------------------ --- ----- ---------------- -------------- --------------- -----
__plsql_vm                       2                               1848468              17     6
  __anonymous_block              1                               1818326             590     5
    __sql_fetch_line13          20                               1100678         1100678     1
    TABLE_COUNT_TYPE            13 APP   TABLE_COUNT_TYPE         521332              31     1
      __static_sql_exec_line55  22 APP   TABLE_COUNT_TYPE         521301          521301     1
    __dyn_sql_exec_line12       19                                133537          133537     1
    __static_sql_exec_line8     21                                 34400            2407     1
      __plsql_vm@1               3                                 31993               4     1
        DBFUNC                   9 APP   PROF_TEST                 31989           31989     1
    R_CALLS_R                   10 APP   PROF_TEST                 27684            9234     1
      R_CALLS_R@1               11 APP   PROF_TEST                 18428           18426     1
        PUT_LINE                18 SYS   DBMS_OUTPUT                   2               0     1
          PUT                   17 SYS   DBMS_OUTPUT                  23              23     2
          NEW_LINE              16 SYS   DBMS_OUTPUT                   0               0     2
      PUT_LINE                  18 SYS   DBMS_OUTPUT                  22               1     1
        PUT                     17 SYS   DBMS_OUTPUT                  23              23     2
        NEW_LINE                16 SYS   DBMS_OUTPUT                   0               0     2
    GET_LINES                   15 SYS   DBMS_OUTPUT                  79              79     3
    STOP_PROFILING               4 APP   HPROF_UTILS                  26              26     1
      STOP_PROFILING            14 SYS   DBMS_HPROF                    0               0     1
  DBFUNC                         9 APP   PROF_TEST                 30125           30125     1
A_CALLS_B                        5 APP   PROF_TEST                128199            9631     1
  B_CALLS_A                      7 APP   PROF_TEST                118568           30617     1
    A_CALLS_B@1                  6 APP   PROF_TEST                 87951           27332     1
      B_CALLS_A@1                8 APP   PROF_TEST                 60619           60619     1
__static_sql_exec_line700       23 SYS   DBMS_HPROF                   67              67     1
__pkg_init                      12 APP   PROF_TEST                     3               3     1

27 rows selected.

Recursive Subquery Factoring Query

WITH pci_sums (childsymid, subtree_elapsed_time, function_elapsed_time, calls) AS (
    SELECT childsymid, Sum(subtree_elapsed_time), 
                       Sum(function_elapsed_time), 
                       Sum(calls)
      FROM dbmshp_parent_child_info pci
     WHERE runid = &RUN_ID
     GROUP BY childsymid
), full_tree (runid, lev, node_id, sub_t, fun_t, calls, link_id) AS (
    SELECT fni.runid, 0, fni.symbolid,
           fni.subtree_elapsed_time - Nvl(psm.subtree_elapsed_time, 0),
           fni.function_elapsed_time - Nvl(psm.function_elapsed_time, 0),
           fni.calls - Nvl(psm.calls, 0), 'root' || ROWNUM
      FROM dbmshp_function_info fni
      LEFT JOIN pci_sums psm
        ON psm.childsymid = fni.symbolid
     WHERE fni.runid = &RUN_ID
       AND fni.calls - Nvl(psm.calls, 0) > 0
     UNION ALL
    SELECT ftr.runid, 
           ftr.lev + 1, 
           pci.childsymid, 
           pci.subtree_elapsed_time, 
           pci.function_elapsed_time, 
           pci.calls,
           pci.parentsymid || '-' || pci.childsymid
      FROM full_tree ftr
      JOIN dbmshp_parent_child_info pci
        ON pci.parentsymid = ftr.node_id
       AND pci.runid = ftr.runid
) SEARCH DEPTH FIRST BY sub_t DESC, fun_t DESC, calls DESC, node_id SET rn
, tree_ranked AS (
    SELECT runid, node_id, lev, rn, 
           sub_t, fun_t, calls, 
           Row_Number () OVER (PARTITION BY node_id ORDER BY rn) node_rn,
           Count (*) OVER (PARTITION BY node_id) node_cnt,
           Row_Number () OVER (PARTITION BY link_id ORDER BY rn) link_rn
      FROM full_tree
)
SELECT RPad (' ', trr.lev*2, ' ') || fni.function ftree,
       fni.symbolid sy, fni.owner, fni.module,
       CASE WHEN trr.node_cnt > 1 THEN trr.node_rn || ' of ' || trr.node_cnt END "Inst.",
       trr.sub_t, trr.fun_t, trr.calls, 
       trr.rn "Row"
  FROM tree_ranked trr
  JOIN dbmshp_function_info fni
    ON fni.symbolid = trr.node_id
   AND fni.runid = trr.runid
 WHERE trr.link_rn = 1
 ORDER BY trr.rn

Notes on Recursive Subquery Factoring Query

Root Nodes and Child Sums Subquery

A function may be called both as a child of another function, and also at the top level, as the second example showed. We detect this situation by counting the number of calls for the functions in the links table (dbmshp_parent_child_info) and comparing with the number of calls in the functions table (dbmshp_function_info). The difference corresponds to the number of root-level calls, and the root-level timings are the timing differences between the function timings and the sums of the link timings.

Link Duplication

As noted earlier, hierarchical queries (both Connect By and recursive subquery factors in Oracle) cause the links below any loops to be duplicated as all paths are followed. In this query an additional subquery has been added, tree_ranked, that ranks the nodes and links by order of appearance. The node rank is used just for information in the main block, while the link rank is used to eliminate duplicate links. Gaps in the “Row” column indicate where duplicates have been suppressed.

It’s worth remembering this because it’s a general feature of SQL for querying hierarchies, and one that seems not to be widely understood. For larger hierarchies it can cause serious performance problems, and may justify a PL/SQL programmed solution that need not suffer the same problem, such as: PL/SQL Pipelined Function for Network Analysis.

Here is a query structure diagram for the recursive subquery factoring query:


I wrote about query diagramming in August 2012: Query Structure Diagramming

Hierarchical Profiler Feature Summary

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

  • Results are organised as lists of measures by program unit and by ‘unit-within-caller’, and can be represented in a call hierarchy
  • Results are reported at the level of program unit call or ‘tracked operation’; all calls to a given program unit within a single parent unit are aggregated
  • Measures reported are elapsed times and numbers of calls, but not CPU times
  • External program units are included in the profiling
  • Profiling is performed, after initial setup, by means of before and after API calls, followed by querying of results in tables, or viewing of HTML reports