oracle23ai and python - eliminate RoundTrips.

TL;DR: Searching for RoundTrips to eliminate between python and Oracle. In this case, we "collect" the individual inserts to do them in a few large "batches". The result was Surprising, in a Good Way.

And then... Some pieces of program I would rather not have to write (re-constructing the wheel...). But Hey, it wasnt too hard, and it Really Helped.

Old Lesson (re)Learned: Row-by-Row == Slow-by-Slow.

Image: Several Cites have an efficient metro-train running next to an ever-jammed highway. I remember notably Chicago. But the view from the train from AMS airport to Utrecht is often very similar.

Background: Processing data (outside of the RDBMS), and TAPIs

Some systems want their data "processed" by python or other tools that are not part of the Oracle RDBMS (yet). Even if I think that taking data to and from the Database is generally not #SmartDB (link to asktom), sometimes this needs to be done. 

But when every individual record (ins/up) becomes a RoundTrip, you will notice.

Luckily, a lot of our tables already have rudimentary TAPIs (TAPI = Table Application Program Interface). And some of these TAPI-functions caused a lot of those infamous Round-Trips.

TAPI - a Good Concept - until it is not...

The concept might be rather old (80s, 90s?), but it still serves. You'll find similar concepts in ORM-frameworks like JOOQ and Hibernate (links)

In our case, our python code will generally handle the creation (insert/update) of a record in a separate function (f_ins_item... ). These TAPIs will typically handle things like: 1) ensure there is a parent-object, or maybe create one,  2) and handle MERGE-functionality when required to prevent insertion of duplicates. 3) verify (or create) the necessary metadata or lookup-data.

This is a Good Idea, as it centralises the logic for tables in a few, easy to find, functions.

Most of these TAPI functions do their Good Work quietly in the background. In our cases, the "create/update of a record" is not the most time-consuming activity of a program, but rather the outcome of a much longer process. Not a noticeable bottleneck. Mostly.

But all of these TAPIs are single-record functions: they act on 1 record at a time. And when processing large numbers of records, that TAPI-function and the round trip(s) it does can become a time-consuming activity. 

And "network" is a funny resource-consumer: you end up with both Application and Database doing seemingly "nothing" until you know where to look (In our case: AWR and application-logs-to-stdout, but this story is not about the "diagnose" it is about the "Fix").

TAPIs causing round-trips - Too Many RoundTrips.

As it was, the most executed statements on a particular system were the Inserts of "Details" in the datamodel: Records at the fringes of the ERD-diagrams that would receive 100s or even 1000s of records as+when details become known about an item (e.g. the "generic datamodel strikes again", different topic...).

The nature of those TAPIs is 1-record-at-a-time. And sometimes that hurts. From application-log (lines with epoch-time printed to stdout) we could learn that the insert-function was often called, and was a time-consumer. The RDBMS had some notable INSERTS as "High Frequency" (top of list for "ordered by executions"), but not as notable inefficient or resource-consuming statements. 

The whole picture of a slow-program, a relatively quiet RDBMS, and the AWR-numbers about executions and RoundTrips, was enough to warrant a little test.

What if we could "batch" those inserts and prove that 1-row-at-a-time was really the in-efficient part of the system ? 

Test: Catching the insert of a record...

For test-purposes, I simplified the table like this (will put link to script below):

The ID and CREATED_DT get generated by the RDBMS on insert. The FKs are self-explanatory. The Real-World case is a record of some 20 columns with a few more constraints (think: optional columns for dates, times, intervals, validity, valid lat/long, various field- and record-level constraints that can take some DB-CPU to validate, but never much....). And the (average)size for records varies between 500bytes and 2000bytes, depending on the item, the source and the label.

The Original insert looked (simplified) like this: 

We have a function that can be called whenever a "label" is detected for an Item. The properties of the label need to be stored, with a few FK-references and various detail-properties that go in the columns or (free-format-ish) fields of the record. 

Needless to say the FKs must exist for this to work. Cases where the FK-parents may have to be inserted are more complicated. And checking of various "validations" for columns can also take code + time. For the sake of demo, this is a much-simplified example.

Notice this SQL-statement is watermarked as /* t1 ...*/ for easy spotting in tests. Watermarking can also be Very Useful in deployment. Just saying.

Also notice: this function does Not Commit. The TX-logic is done elsewhere.

In short, several INSERT statement of this nature were The Most Executed stmnts from our problem-programs...

Buffering in a list, the Simple Concept.

The fact that all(?) insert in the original version go via a single function is a Great Start. All we have to do is "catch" the inserts, collect a sufficient number of them, and then send those to the RDBMS as a single statement using something like cursor.executemany (see this good example in the docu..)

In pseudo code:

That pseudo-code speaks for itself: store new records in a list (of records), and insert them when you have a significant collection. The Inspiration came partly from what I knew about RoundTrips and previous programming effort. And from a Very Readable example that can be found in the python-oracledb doc on "Batch Execution" (link).

Two main things to check in this concept: 1) Do Not Forget to check and insert any leftover items in the list before program commits or exits. 2) Avoid errors with an Empty-list, e.g. when no records at all are in the list, stop the function from throwing an error.

Other than that: Piece of Cake, right ? 

Note: Python-adepts may recognise this as "using dataframes". Very Similar. Except that at this point, I use self-coded lists for simplicity and demo. It is quite possible that our dev-team will, over time, adopt some form of data-frames (Pandas, Apache-PySpark) in future. You can lead a horse to water.... but Maybe Later.

Late-Edit: As I am writing this blog, Christopher Jones is writing about DataFrame support in the latest python-oracledb release. Check this!

Let's put it to Code:

Note: the complete, hopefully runnable, program and scripts are linked at the bottom of the blog...

We start by defining some necessary (global-)variables and constants:

The implementation will need a (global-) list to add records: itl_list

It needs a length at which to do the inserts and re-initialize the list: itl_list_max_len

And we have the SQL to do the work: itl_list_sql_ins

The SQL-statement does not have to be defined global, but putting it here cleans up the def-function code. In practice, having the SQL inside or near the function can help with coding and code-reading. You choose whatever is convenient for you.

With this in place, we can re-write the insert-functions, in two parts: First the function to catch the records:

This "insert" function no longer interacts with the RDBMS, instead it appends the records to the (global) list. 

In practice, there might be additional logic to check the "validity" of the record before adding it to the list. I've left that out in this example for simplicity.

But the add2list Does check for the size of the list. And when itl_list_max_len is reached: it calls the function to insert the records from the list and to reset the list.

The function that does the actual insert looks like this:

The special case is an empty-list: Do Nothing and return 0, no records inserted.

If there is data in the list: then insert it. 

Note that in this example, we do not (yet) check/re-check the validity of the data before handing it to the cursor. Any serious data-anomaly could throw a nasty error.

As return-value the function reports the actual number of rows processed by the cursor, assuming that it was the nr of inserted records.

This code "compiled and ran" and all seemed Well..

So Far So Good. But did it Help ? 

Let's Race It....

To compare, I pasted together a program that will do two loops of n_sec. One loop  of original, individual inserts. And another loop of n_sec of list-buffered-inserts. Let's see what comes out faster...

Note: On early testing, I started with n_sec = 120sec of inserts. The Array-insert was so fast it threw an error: ORA-01653. Good Start. I adjusted the timings downwards a bit...

So I have two while-loops that each try to insert "records" as fast as they can for _only_ 10 seconds. 

The first loop does 10 seconds of "individual inserts", it uses the original call for each individual record. The results to stdout looked like this:

Notice the number of loops (records): 2109, or 210.9 records per sec. Then notice: 2113 RoundTrips (minus the 4 from program-startup). Yep, 1 RT per record. Reporting the stats and the commit will add 2 more RTs, and bring the total to 2115 RTs before the next test starts.

(Also notice, I sneakily eliminated hard-parsing to beautify my results a little... )

The second loop does 10 seconds of append-to-list, with the occasional insert-into-table when the list gets to 1000 records. Stdout report looks like this:

Wow... That 10sec loop inserted 339.339 records....? A factor of 150x more. No wonder the first test hit my tablespace-size-limit.

First verification: count (*) in the database, Yep: over 600.000 records (there was a 1st run to eliminate the overhead of hard-parses...). Looks correct.

Second verification : the nr of RoundTrips. Those 339.339 new records, at 1000 records per execute, would have caused 340 RTs.. The reported nr of RTs is 2455. And minus the previous 2115 RTs, that is ... 340 RTs. That seems to concur Very Well.

Final check: V$SQLAREA (and counts) after two(!) runs of the program:

The Statements show up in the Shared_pool, and look at those numbers:

The individual-inserts /* t1 indiv */  have consumed about 273 microseconds per execute, for 1 row per execute, or 273 microsecond of DB-time Per Row.

The list-insert, marked /* t2 list */, with 1000 rows per execute, has consumed 12,854 microseconds per execute, but with 1000 rows per execute, that is Only about 13 microseconds of precious DB-time consumed per Row. 

This Thing Rocks!

Some sobering thoughts...

This is essentially an Old Lesson (re)Learned: Row-by-Row = Slow-by-Slow. We Knew this since, ah.. 1995.

The First Thing we missed with the new function was the RETURNING-ID. All of our TAPI functions so far return the ID (primary key) of newly inserted or merged record. In the case of bulk-detail-records that is not a problem. But for inserting new meta-data, new lookup-data or otherwise data that is needed for further processing, this can be an obstacle. In our case, we will only build list-inserts for records where we do not need that return-value. Minor problem so far...

Validation of records by the RDBMS, e.g. Constraints inside the Database, can be more complicated on bulk-inserts. Bulk-error processing is possible, but not always simple. With individual records, it is easier to catch errors with try ... except blocks. In our case, there are records where we dont want bulk (yet) for this reason. You decide how important this is to you.

Extra code means additional dependencies and additional (future-)maintenance. Especially difficult to argue when written to "work around a problem" rather than to add something (functionally-)useful to a system. In this case, I had to write two functions to replace the original (TAPI-)insert. And future programmers/users need to take into account that the leftover-data in the list needs 1-more-insert to clear out.

For this example: Someone will forget to purge the array at some point, and (inexplicably) loose the contents of the last batch...

I would recommend to only apply this trick when you Know it is going to make a Big Difference, and when your team is capable of understanding the additional (brain-)work.

Alternatively, you can search for existing solutions. Certain DataFrames for python may already solve this problem for you. The pandas-dataframe (link) looked promising, but on first-search it did not provide exactly what we were looking for.

Further items to explore..

Record-types. The equivalent of what PL/SQL has: EMP%TYPE could help in defining a structure to hold data. It could make the lists easier to manage and it can do some data-checks before adding data to the list. It would reduce potential for errors on the actual insert. Maybe Later.

Data-Frames or similar toolkits might "do the work for us". For java there are JOOQ and Hibernate. Python has several DataFrame options, such as Pandas and Apache-pySpark and some of those may have potential. Maybe Later.

Geeky: How big can the array be (in nr-records and/or in memory-footprint) before it shows signs of deterioration? For the moment, any number above, say, 100 will clearly benefit the system by reducing RoundTrips and overhead. But is there is an optimun or some upper-limit. Maybe Later.

Summary: Batch-Processing (array-processing) Works !

From this (over-simplified) testrun, I want to point out the Two Main Benefits of Array-Processing:

1. The program managed to insert 150x more records in the same 10sec interval. That is a clear increase in capacity for the app-program. The biggest benefit is in reducing the overhead, the call- and roundtrip-time per record.

2. The consumption of DB-resources on the RDBMS-side is much more efficient as well. Because the RDBMS can now handle "bigger chunks" per call, it spends less time on the same amount of "ingest data". This Benefits the RDBMS as well.

The numbers on this test Really Surprised me. Again. Despite using systems with only single-digit-millisec latency. And I knew RTs were costly, I've seen + fixed this kind of problem before. But I didnt expect the difference would be This Big. 

This problem is as old as the app-rdbms dichotomy.  And yet we dont seem to learn.

This test in particular also illustrates how un-necessary RoundTrips can slow down Both the App and the RDBMS: not just by losing time waiting for latency, but also from the incurred additional processing. 

RoundTrips are the Next Important Challenge in IT...

This test demonstrated: Both components, the Application and the RDBMS, Gain from batch- or array-processing and reduced RoundTrips.

-- -- -- -- -- End of this blogpost, for Now -- -- -- -- --

Appendix 1: links to Scripts.

tst_ins_labels.sql : set up the datamodel.

tst_ins_label.py : the demo program with two while loops

You need following "importable files" to run the tst_ins_label.py program:

ora_login.py : the login utility (uses dotenv) and the session-info.

prefix.py : contains pp ( *argv ) to print to stdout with timing info.

duration.py : my stopwatch, time-measurement for python programs.

.env : used by dotenv to store + get credentials and other info.

And to verify the results, you can use:

tst_2arr.sql : view SQL in shared_pool, and count records in src_item_label.

Feel free to copy or even re-type. 

Re-use of code is often a myth, unless you have typed or at least modified the code yourself.

If you have suggestions for improvements: Let me know. I'm always interested in discussion these things if time+place allow. Preferably in the margin of a Good Conference, or on one of the social channels (bsky, slack, email...).

-- -- -- -- -- End of this blogpost, for Real -- -- -- -- --

Oracle23ai - a SQL-Macro for Epoch - The Better version.

TL;DR: I had a function to produce "Epoch", similar to python. When I tried to speed up function-calls by using a macro I found an interesting side-effect. Macros are "substituted into the statement", and that has consequences.

Spoiler: You Should RTFM (link) before building Macros.

But in the end: I got it to Work, and Arguably Much Better.

Image: a camera with a Macro-Lens - nothing to do with SQL-Macros. But that lens also peeks at details.... 

Background: a function, then someone suggested an SQL-Marco.

Originally, I wanted my RDBMS to produce epoch-values similar to python, with the epoch-seconds, and fractional values to supposedly measure milliseconds and microseconds, if possible.

Due to the nature of the function-call, with use of the function in queries the resulting epoch was not Atomic: multiple occurrences of the function would return different values, as each call would happen at a slightly different point in time.

When I was playing with the function to get "epoch values", several colleagues suggested I should turn it into an SQL-Macro because that would be even Faster.

So I tried that "macro" idea. With mixed results. But I think the End-Result is Better than the function.

Just add SQL_MACRO ( SCALAR) ?

I took the source code for the function from the previous blog (link), and tried to turn it into a macro. Called it m_epoch1 (suffix the number 1, because I did expect to do a few tests/attempts, I was right). First Attempt:

Error: a macro has to return characters, not a number. I didnt think long, and just put in VARCHAR2. That worked:

Didnt think much of it, I assumed any necessary conversion would happen automatically. And I would check formats etc. later. (I would regret this..)

The usual test at the bottom of the source-script was a bit funny. The resulting values looked ok at first, close enough to the values from python time.time(), and close to my unix date +%s. But something didnt seem right. This is what my tests looked like:

The front-terminal shows a few queries using SELECT m_epoch1, and I tried the date-command straight away. The top-left terminal also shows the result from python. The value produced by python. At first sight, all looks reasonable.

The python value is typed about 6 sec after the linux-date. That was to be expected.

But the results from both of the SELECT queries show All The Same Values. And the values are about 140 seconds Older ???  (I did Not wait 2min in between....).

Something is Wrong...

I tried a more simple test: 2 identical selects with a deliberate sleep of 5 seconds in between, but the results, the epoch-values, of the 2nd run of the same query are Identical to the earlier call...

That Is Definitely Wrong. 

Same epoch reported by 2 queries, 5 sec apart.. ?

I did several more test-queries, even comparing results from function and macro in the same query. A lot of results didnt make sense. I started noting...

Firstly, every query, every column, every call to the macro/function used to yield a slightly different value (as it did with the original function). But with the SQL Macro it does Not ??

Secondly, some query-results seem to remain constant over time. But not always...??

Thirdly, the values now seem to increase from Right to Left, where similar tests with the function-version, f_epoch, evaluated from Left to Right. 

Fourthly, the values remain the same over the Rows of a query, e.g. subsequent rows do not seem to get later epoch-values, as they did with the function f_epoch. 

Fifthly, I found that when re-run an Exact query, the same answers come out. E.g. it looks almost like there is a result-cache for the queries.. (I didnt have a result-cache configured, that I know of. I even checked, as I have presented and blogged on that result-cache topic back in .. ah .. 2016 - link) 

All rather funny behaviour from the "macro" version.

I did several things: I started Reading the RTFM on SQL-MACROS (and the blogs by Tim Hall, sometimes dubbed as "The Better Manual"). And I asked some Oracle-Knowledgable Friends on slack about behaviour of SQL Macros. And within minutes, Erik van Roon, who has done several ppts on macros (link), had the clue...

The Solution: SQL MACROs are "injected" at parse time.

Erik's reply was: "If you get Constant-values from an SQL Macro, you do something Wrong. The Macro gets evaluated at Parse Time, and Only at Hard Parse."

My Lightbulb Moment... 

That explained most of my funny results. The macro inserted a "constant" value at (hard) parse time. and that value, the epoch-time at hard-parse, remained with the query, until the next hard parse.

Tim even shows how you can do a. 10053 trace and see the query-after-the-macro. And in my case, my sloppy-written macro would "inject" the epoch-value written as a string representing the litteral number. And that litteral would stay their until the next hard-parse.

For my solution, I had to go back to the manual and learn how to properly write an SQL MACRO...

It is the q'[ Quotes ]', Stupid !

Here is how my good, Working, version looks now:

By returning the part in the q'[...]'  it gets "injected" into the statement. And now the results are more promising.

Verify: Repeated, identical queries should return increasing, epoch-values:

Looks good. Now, every execute of a query gets a fresh epoch value.

Now Verify Atomicity: Multiple epoch-columns in a query should return same epoch-values for all calls to the epoch:

Correct! All epochs, regardless of row or column, have the same value. 

And the fractional seconds show that the epoch corresponds to SYSTIMESTAMP for the query.

This is actually more like the behaviour that I would want from an epoch-function in SQL. 

In short, I think we just Improved the Correctness for our Epoch.

Further research: Later...

So we improved on the "epoch", and I would recommend using the SQL Macro here whenever possible. ... Unless (like me sometimes) you were interested in some kind of "precision measurement" during the execution of the query. 

Just let me show you this:

Every Row in this SQL does two calls to the function f_epoch, and also displays the value from m_epoch2 and the factional seconds from SYSTEMTIMESTAMP.

Notice how the values of m_epoch are slightly earlier than the values from f_epoch. The m_epoch got inserted at the start of the query, together with the timestamp. But the f_epoch values got added (called) as each row got produced, and are thus a little later. This gives us some insight into the processing of the query. Might be interesting for some research. 

Maybe Later.

Speed Test: how long does it take...

As with the function-versions of the epoch, I did some testing with large-ish numbers of calls/records/queries.

I watermarked the SQL in the test with comments.. For example /* tm1.1 */ : It will query with 1 column-value of m_epoch, and get 1000-rows (connect by <1001)

And then tm1.2, tm1.3, tm1.4, tm1.8 : Ditto with 2, 3,  4 or 8 values in the row (more use of macro, more use of systimestamp...).

Those could be compared to similar calls to the f_epoch, the function from the previous blog, where I used  tf1.1 and tf1.4. 

The results:

First look shows: the SQL Macro outperforms the function-call. 

Even getting 8,000 epoch-values (1000 rows, 8 columns, /* tm1.8 */ ) using the macro, is faster than getting 1,000 values from the function in query /* tf1.1 */  ... 

This makes sense: every f_epoch is a "separate call", whereas the m_epoch is inserted at the start of the query, and requires "no further calls".

Remember: we found about 8microsec per call to f_epoch, which still +/- concurs with the numbers in the results for /* tf1.1 */ and /* tf1.4 */ in this test. 

The values for the queries using the macro for 1, 2, 3, 4 and 8 columns are so close together that I dont want to do any calculation on those yet. 

There was however 1 consistent anomaly: it was strange that the 1-column resultset  ( /* tm1.1 */ ) should consistently be slower than the queries with 2 or more columns. Later!

(the above test is done using script tst_epoch3.sql, link below)

Yep, The SQL Marco is Fast....

Just to dig a little further, I tested with more rows and columns.

I also tested with and without set termout-on/off: the termout had no impact on execution-times, but made my tests go smoother, because I didnt have to wait for the endless scrolling terminal.

Because the epoch-value seems too get "fixed" at (soft)parse time, and the number of epoch-columns seems to have little impact, I varied the number of rows as well, 1000, 2000, 4000, 8000 (test in script tst_epoch4.sql, link below):

Interesting, but somewhat expected: The number of Rows now determines the (cpu) time the query consumes. The fastest group of queries is the one with 1k-rows. Even if the 1000 rows contain 8 epoch-columns (test tm1.8.1), producing those 8000 epochs is a lot faster in 1000 rows, than it is in 8000 rows x 1 column: test tm1.1.8.

The blue line indicates the jump from 1k records to 2k records, and the first jump-increase in cpy_per_exec.

And notice that in general, the use of the SQL Macro is much faster, and more "scalable" due to a lot less activity, than the conventional function-calls from the earlier version of f_epoch. 

Conclusion so far: That Macro Flies !    ( ... in this case)

About that anomaly... Parsing ? 

In the process of testing, I accidentally found the (probable) cause of The Anomaly of the First Query: at the bottom of the timing-results we see the exec-time for a manually done, one-time SQL: 

select / tm0 1st macro */ m_epoch from dual ;

This query appears on the last line of the test-results above, and it has only been called Once... 

By doing that one-call, the First Call, to the macro (after shared-pool-flush, or after re-create), I seem to "prime" or Parse the SQL Macro. If I leave that out, the first query in the test-series takes much longer on the first run, and that affects the average for this query. This explained the anomaly for tm1.1 in the previous test...

Another Item "found", and something to inquire when I next meet People Who Know Much More then me..

Wrapping it up: The Macro is The Better Version.

About the SQL Macro: I think that In This Case, the use of the Macro is more appropriate than the function. Especially as I gave some warnings about "Atomicity" in the blog about the creating of the function (link). But if you want to measure "inside the statements", then the function-version is what you need. 

The speed-tests show that the use of SQL Macro here also makes a difference. 

The anomaly I found on "first call", and where I worked around with a manual one-macro-call query, is probably explicable, but I dont have the inclination to read- or dig-deeper on this Right now. Later.

I'll put links to the source files below so you can do your own replay of some of this.

Remember: the Best re-use of code is once you have typed it yourself... 

Enjoy!

-- -- -- -- -- End of this blogpost, for now -- -- -- -- --

Appendix: Scripts.

mk_epoch_macro.sql : creation of the macro and some first-tests.

tst_epoch3.sql : testing to compare macro and function.

tst_epoch4.sql : testing with less and more rows.

-- -- -- -- -- End of this blogpost for Real -- -- -- -- --

Oracle23ai - get the Epoch (like python and linux).

TL;DR: Using Oracle23ai and python, I wanted an SQL-function to produce the "epoch" value similar to a python call to time.time(). And of course I wanted the fastest possible version...

Oh, and a note on "Usage": Preferred usage is in a CTE... You'll see.

The image is an atomic clock from the National Institute of Standards and Technology (NIST). One of the most Exact Clocks in the world.

Background: Using python time module for measuring time.

From the unix "date" command, we can get the epoch, which is defined as the number of seconds since 01-Jan-1970 (link):

date +'%s'

That number looks familiar to anyone who has used epoch-values. And now we have python, it tries to do better and adds the fractional seconds to that value:

time.time()

Having such precision was very tempting. It was much more precise than the old-fashioned SYSDATE that I used in most of my legacy-scripts. And since way back in version 9i, Oracle has SYSTIMESTAMP, which is potentially accurate to the nanosecond (link to Oracle doc). 

Here are three terminal windows to compare the options :

At the top, the terminal window shows the unix/linux-date, it returns whole seconds, with no factional component.

Middle-window: Python pretends micro-second accuracy (and the time-module even has some nanosecond-functions if/when the hardware supports that accuracy).

Lower-terminal, SQL>: Oracle _can_ do fractions of a second up to 9 decimals with the FF9 format-mask, but it is actually more like 6 decimals, e.g. microseconds. Still not bad.

So with SYSTIMESTAMP, the basis is there to build a function that produces the same kind of number as python: a floating point number of epoch-seconds, with decimals that go down to milli-, micro-, or even nanoseconds.

The function: use SYSTIMESTAMP to produce an epoch number.

My first attempt was relatively simple and explicit: Calculate the large nr of seconds up to today-midnight, then add the (precise) number of seconds (and decimals) that have passed since midnight. Call that version one, f_epoch1

Note that I use a two-step process, because TO_CHAR does not have a format-maks that covers "epoch seconds" (not yet?). 

First I calculate the nr of Seconds from Epoch up until midnight-today. 

And then I use a format mask to determine the number of seconds (with fraction FF9) from midnight up until Now.

Adding the two gets me the Epoch, with fractional seconds, similar to python.

And that seems to come out nicely. Here are the first tests:

Notice the first query: select f_epoch1 from dual. Seems fine, and the value is close to what my linux date +%s command produced. 

Now notice the second query, multiple-columns and multiple-rows query: Selecting multiple f_epoch inside one query yields Different, Increasing, values for the epoch. The function is evaluated multiple times, and the order is from left-to-right and from top-to-bottom.

This May be Counter Intuitive, and even Un-Desired ! 

Remember that SYSDATE and SYSTIMESTAMP are generally Atomic, immutable, during the execution of query.... More on that in a moment.

For the moment we conclude that every column in the query seems to be a separate call to the function, and yields a different (fractional) time

I did a python-call to time.time(), to compare outcomes. You can see from the epoch-values that I took me approx 5 seconds to type the python-commands.

This all Looks Promising: I can get an Epoch-value.

Preferred Usage: in a CTE (With epoch AS...)

Some people will not like the fact that the results of the function varies per row and per column. We are used to SYSDATE and SYSTIMESTAMP being "constant" inside a single query. 

To this end, I recommend to use the f_epoch in a CTE expression so as to ensure there is only One call, and the value will be "constant" inside the query that uses it.

Here is how I intend most usage:

Notice how all the epoch-values are now Atomic, identical. And the MATERIALIZE hint is used to ensure the CTE is evaluated Before the main query, and only Once.

If an Atomic Epoch is what you want / need / expect, you should to be Aware of this! 

(there is no relation with the atomic clock in the image above, but still...)

Testing: Execute it a few thousand times...

As Oracle-geeks, we are obsessed with "performance", and the first thing I wanted to know: how fast is this. Or: how many CPU-(micro)seconds is this call going to take.

Here are some queries that call this function 1000s of times...

The first query, labelled /* t0 ...*/ , is the 0-measurement, included for calibration purposes. It does not call the function, but should give us an idea of the overhead for a query that returns a number similar to the epoch.

The other queries call the function with one or more columns. Running these queries multiple times should give us an idea of how long a call to the function takes. (I suggest 10+ runs to get rid of the parsing-overhead).

We run the tests 10s of times, and check the CPU- and Elapsed-times in v$sqlarea with the following query:

The zero-query takes 955 microSeconds to return 1000 rows. That is roughly one microsecond per number-returned. Consider this as "the overhead".

The query with 1 single epoch-column  takes 20,979 microseconds to return 1000 epoch-values, roughly 20 microsec per epoch-call. This is an upper-limit for the time we should find for a call the function.

The query with 4 epoch-columns takes 67,479 microSeconds, e.g. some additional 46,000 microseconds more to return 3,000 additional epoch-values. That would put the call to the epoch-function at between 15 and 16 microseconds.

The other values confirm this: the average call to the epoch-function is in the order of 15 microseconds. 

Not Bad for Oracle running in a container on an old macbook-pro. But I had to try a few more things to try though: Reduce the code, and use Pragma-UDF

Improving: reduce the code.

First, as an old-hand-coder, I tried to reduce the number of statements in the function. I eliminated the assignment to variables and the sum of two values. With some shuffling, I could get the whole function to be one single return-statement. Call that f_epoch2:

Compared to the original, I have eliminated three variables in the declare-section, and the equivalent of 2 lines of code in the function-body.

After verification (the results still came out correct...), I could test with that new version and it was slightly faster. 

Small Victory.

But there was more to try.

Improving: PRAGMA-UDF

When you RTFM on the use of stored-functions the standard tip is to use PRAGMA UDF (link). This should tell the compiler that you want to use the fucntion in SQL-statements and the compiler will try to optimize for that. 

Hence I tried this. The same, reduced code as version 2 but with added PRAGMA UDF, and called it f_epoch3 :

And while I was looking at the code, I tried a few more things, especially around the placement of SYSDATE and SYSTIMESTAMP. I figured the less calls the better, so I came up with this:

The function now does only 1-single fetch of the SYSTIMESTAMP, and no more calls to SYSDATE. On first test, this also seemed to work well. 

I now had done my compulsory "tuning + improvement" activity.

Time to Race: which version is fastest...

Every function got called in two queries and each query returned 1000 rows. 

One query would return one single column (e.g. 1000 calls to the function) and the other would return 4 columns (e.g. 4 calls to the function). Here are the results..

The numbers are never  exactly the same on every test, but the results (on the same machine) are always around 5-10% similar. And the order of the versions is Always the same: version 3b is the Clear Winner.

If we compare the queries t3b.1 and t3b.4, we can roughly estimate the time consumed for a call to f_epoch3b:

Every query returns 1000 rows, with either 1 call or 4 calls to the function. The difference between the queries is thus 3000 calls.

The difference in time per execute is 34,431 - 10,913 = 23,518 microseconds.

That would put the time for 1 call to the epoch-fuction at about 23.5 / 3 = approx 7.9 microsec. An improvement over the original version.

Verdict so far:  8 microSeconds to return an Epoch similar to the python time-call.

(with supposedly micro-second accuracy, -smiley-, but not really...)

Wrap up: Got it working, and got some lessons.

I got the function to do what I wanted: produce epoch-values with a suggested precision, apparently up to 6 decimals, e.g. microseconds (but not really that accurate...)

And from the various versions, I picked f_epoch3b as the winner. The seemingly fastest of the variants, and I used that code to create a final f_epoch.

You should be aware of the (non) Atomicity of the function. And if you need an atomic epoch value in a query: use the CTE and Materialize it.

The measurements, for what they are worth, show that on this system (an old MBP from 2013...), the call to the function takes about 8 microSec.

Tweaking the code to reduce statements made it somewhat faster.

Adding Pragma-UDF Definitely Helped.

As a by-product, I re-used some code (ideas) to measure SQL-queries by picking data from the shared_pool. 

The code for the various functions, should you want it, can be found in the links below. 

I did also try to pack the code into an SQL-Macro as well (Macros are possible as from Oracle version 21c). That works, and it is Even Faster. But that had a side effects. Topic for another blog. Maybe Later.

-- -- -- -- -- End of this Blogpost, for now -- -- -- -- --

Appendix A: The Scripts. 

Feel free to copy and re-use. But dont hesitate to code your own. People tend to re-use code more if they have typed it themselves... 

mk_epoch.sql : Creating the functions. File contains all old test-versions.

tst_epoch1.sql : Some queries to measure time.

tst_epoch2.sql : Comparing v1, v2 and v3, with v3b as winner...

-- -- -- -- -- End of this Blogpost, for Real -- -- -- -- --

Oracle23ai and python - Roundtrips.

 TL;DR: I use Oracle23ai and python. Measuring the time it takes to call cursor-functions reveals when RoundTrips take place. It also shows how prefetch and arraysize affect the round-trips.

Background : Investigating RoundTrips.

When using python and Oracle, we ended up with some python code that did too many round-trips and investigated the behaviour. I'll try to demonstrate some of the findings.

Some of what I demonstrate is also nicely pointed out in The Documentation... I just confirmed it.     

For the demo, I use an instrumented copy of "do_sql.py", which allows me to easily send all kinds of queries to the RDBMS and observe the behaviour, notably the timings. 

Earlier work on this problem can be found here (link to Latency-blog). And one of the outcomes was that on that system, the average RoundTrip time was about 1.5ms.

Rolling balls  - waiting for all of them to roll down...

A program that measures running of Queries.

To experiment with queries and timing, I constructed do_sql_times.py (sourcecode in link below). It prints out timing-data (to microseconds, or µs) to stdout. And when retrieving rows from a cursor, it reports the nr of microseconds it takes to get/print every row. 

The essential python code looks like this:

This is the code to get cursor-data, with minimal extras and overhead. (apologies for the comments, I do tend to leave a lot of notes inside code...). 

The program (link to previous blog) can take arg1 as the SQL to execute, hence you can do...

python3 do_sql_times.py "select empno, ename, sal from emp " 

And Here is a demo-run retrieving the well known EMP-data :

Notice the following on the first 4 records:

The 5,517 MicroSec (5.5ms): time to retrieve and display the 1st row.

The 70 MicroSec: time to get/display the 2nd row.

The 1,713 Microsec (1.7ms) : time to get/display the 3rd row.

The 70 MicroSec: display of 4th row...

The display of all subsequent rows then takes less than 300 MicroSec, with most in the 2-digit range (e.g. significantly less than 1 ms)

If you re-run the program with the Exact same SQL-stmnt, the time for the first row tends to go down from 5.5 to about 2.0 ms. This is most likely the effect of the Parse (on first run) and re-use of the SQL-stmnt from the Shared_pool. You can confirm that by flushing sh-pool or running slightly different SQL-stmnts but I wont go into that detail now, maybe for later. 

In most of the following tests, I display "repeated runs" of the program with the "parsing effect" removed.

In Detail: First check for the Overhead...

To start exploring, lets first show the program running with 1 row from dual, like this:

_> python3 do_sql_times.py "select 1, 'one row' from dual " 

The program will report on various stages, like doing imports and defining helper function, and then starts the Main code. 

First part of stdout looks like this:

After the imports and definitions, the ora_login shows where the connection goes (yes, I still use scott/tiger...). 

Ora_sess_info then reports the session statistics right after login, so we can later discount those as "overhead" or "initiazation work". In most cases, the logon (Thin Mode here...) is 1-3 CentiSec of DB-time, 3 RoundTrips, 10 executes and 4 usercalls. 

The actual use of ora_sess_info adds 1 RT,  1 execute, and 1 usercall...

(Yes, you can use snapper-by-Tanel (link) or similar tools to observe a session, but I want my python-code to do its own reporting, independent of other tools. And I might add some of this stuff to In-Production-Running-Code later) 

Hence, at the point of creating the first cursor, we are at 2-3 CentiSec, 11 executes and 5 usercalls (also: see earlier blog, link).  

And most important (topic of this blog) : We now Know this program does 4 (Four) RoundTrips before arriving at the cursor. Keep this in mind for the next testruns.

In Detail: Test a Very Simple Query... 

The program is now ready to create a cursor and do some SQL. And using the same stmnt as above, this is how the data from the query comes out:

 

The retrieval of that one row took 2ms 

And only 1 RoundTrip: total 5 RoundTrips, minus the known overhead of 4).

Just to demonstrate the effect of "parsing", when I change the text of the query (add two Capital letters), that provokes a new parse, and the retrieval time suddenly becomes ... 

A whopping 4.8ms now. 

But still the same nr of RoundTrips.

I also added the "parse count (hard)" to the reporting of the stats. I can not quite prove-beyond-doubt, but given the reported parse, I am fairly sure this extra time is due to parse-time of the 'new' query. I notice the same effect on other queries: 1st run generally takes about 2ms more than subsequent runs of the Identical query.

And indeed, after re-running the same query again, time for first row goes back to about 2ms and no more hard-parse reported... I am now 99% sure this is parsing: 

QED.  

You can Check for yourself: link to programs below. Feel free to try it out. 

And... the "benefit of the shared_pool" is demonstrated again...

Also notice: the need for parse does Not cause additional RoundTrips. A cursor.execute of a qry does the necessary parsing and the initial fetching all in 1 call, one RoundTrip. The separate options to parse statements are something to verify later, but for now out of my scope.

(note to double check this with the docu, and with Christopher Jones at Oracle - there could also be some python-optimising going on behind the scenes)

Now lets retrieve more data...

Next is to try and retrieve more rows, and possibly see the effect on nr of RoundTrips and other time consumed. We already spotted 

The standard trick to get a series in Oracle is connect-by, and we start again with 1 single row:

We notice the same 5 RoundTrips as on the query to the DUAL table. And we know the rest of the program contains 4 Roundtrips. Hence, the execute of the cursor seems to have added 1 RT.

Now try 2 rows:

Suddenly we see 6 RTs. Minus the known-overhead of 4 RTs  this query now seems to have caused 2 RTs. 

The extra time needed to get the 2nd row was (only) 78 microsec. 

But notice the timing info on the prefix-lines (highlighted): After the 2nd row from the cursor it took ... 460735 - 459081 = 1654 Microsec (1.7ms) before the next empty line was printed-out. 

In the earlier run with 1-single-row, there are only 57 MircoSec for that interval. 

So, on asking for 2 rows, we already got an extra RoundTrip, and something consumed 1.6ms at the end of the cursor-for-loop. That was probably that RoundTrip. Remember from previous blog: on this system the avg RoundTrip was about 1.5ms...

It looks like after the two rows, there was a RoundTrip that resulted in (the detection of) End-of-Set.

Let's try 3 rows...

Still only 6 RTs (e.g. the query caused 2 RTs). And the 3rd row took reportedly 1857 MicroSec. But the detection of the End-of-Set took only (553- 472  = ) 81 Microseconds.

Now 4 rows, check the output:

Still only 2 Roundtrips (e.g. 6 minus the known overhead of 4). And the time between the last row and the empty line is only 72 Microsec.

When retrieving 10s of rows: no more "slow rows" and no more RoundTrips get reported. You can now maybe guess where the next additional roundtrip got in...

Yep, at row 103 (and another one at row 203):

Notice the number RoundTrips is now 3 (7 minus the overhead of 4). This next additional RoundTrip only gets added at 102-103-rows. And this probably reflects the arraysize (default 100).

NB: Of course I did confirm this also by explicitly setting cursor.arraysize on a few re-runs. You should try...

Wrap up : Prefetchrows and Arraysize.

These test-runs shows the effect of the cursor property: prefetchrows, default set to 2. But maybe not quite as I had expected. Fetching 2 rows still took 2 RoundTrips, probably because the session has to confirm There Is No Third Row (check?).

Then there is another Roundtrip every 100 records, caused by arraysize.

I did confirm this by playing with both prefetchrows and arraysize a while ago and watch the effects. For example, my tooling function ora_sess_info() has prefetch set to 20, to allow the anticipated number of records to be fetched in a single excute and for-Loop and thus only incur a One Single RoundTrip.

I suggest you read up on the relevant pages (link) and try it out for yourself.

From reading The Documentation on these topics, I Learned a few things, and I got a few ideas for "tuning" our applications. 

But one of the main problems (for me) is the processing of single-records or small set, either retrieve or insert/merge. 

If time + energy, I have a few more ideas for testing out. Later.

-- -- -- -- -- End of this blogpost, for now -- -- -- -- --

Appendix 1: links to Scripts.

do_sql_times.py : the program with timing-info added

ora_login.py : the login utility (uses dotenv) and the session-info.

prefix.py : contains pp ( *argv ) to print to stdout with timing info.

.env : used by dotenv to store + get credentials and other info.

Appendix 2: notes..

Check that the extra time on 1st row indeed is the parse-time (99% proven?).

Check that the extra RT at 2 rows is indeed to confirm End-of-Fetch.

Check for effect of size of cursor-results, notably large sets.

Check for vector-results: extra fetches? extra RTs? extra time ?  We rarely retrieve vectors. We store them, 1-by-1, with often multiple secs in between. The overhead of RT on vectors is not a big factor (yet??). Later!

-- -- -- -- -- End of this blogpost, for now -- -- -- -- --

Oracle 23ai and python - Beware of Latency and Roundtrips

 TLDR: While investigating the combination of Oracle23ai and python, I stumbled across some test-code and findings that may be useful to others. Lets start with the Latency.

Aim of this exercise was to find "Roundtrip and Latency Overhead" for a given connection or program. Chattiness is damaging with high-latency connections.

Chattiness: Comic-character Achille Talon is Chattiness in Person (google him!)

Background: running python code.

In general: this "cloud-only" industry needs to start understanding Latency.

Most (all) of my python work is just plumbing to get data to/from the RDBMS. But in having some python jobs "deployed" into containers in various locations, I have to either prove or disprove that "Bandwidth" or "Latency" are problems. 

This turned into an obsession with Timing (link to previous blog), and especially Round Trips.

Spoiler: it is not often Bandwidth, it more often Latency and Chattiness... If you do enough round-trips, that latency adds up.

I've started carefully by measuring some response-times, and trying to get a grip on how latency (expressed as time, mostly milliseconds or microseconds).

(turned out to be more than one blog-story to tell. stay tuned..... ) 

Why measure all this..

If I can get there, my aim would be twofold:

1. Measure and Report the (average..) Latency or RoundTripTime for a connection between a specific app running and an instance.

2. Measure and Report the nr of Roundtrips for a given program, depending on the amount of data to process.

Knowing both values will help to decide on placement of components: how big is the impact of reduced latency, and help to predict runtimes. But these measurements should also stimulate coders to try to reduce round-trips.

Caveat: This is still Simple and very Basic tooling.

In the examples below I will use very basic, straightforward connections. Most of my tools are stand-alone and do not have (and do not want) the luxury of the Oracle Client Library. And I do not use (do not need...) connection-pools.

As I was (still am!) a python n00b, some of my code may seem overly simple to more experienced users. Quite often I discover that "my problem has been solved by someone else, 10yrs ago...". Feel free to let me know where I need to improve.

Connecting and first measurements.

To test things out, I used a copy of do_sql.py (links below) from an earlier blog, and some utilities I constructed for use with python to ease login and to report some statistics on the connected session. I defined some funcions:

ora_logon (): returns a connection (or kicks out an error if not...)

ora_sess_info ( some_conn ): shows metrics from the connection.

pp ( args* ) :  print output, prefixed with the sourcefile-name and a timestamp

In the my (test-)program, do_sql_mtrcs.py, I will first use them to do a Logon, e.g. open a connection, and report the metrics. Start of the program looked like this:

The first version of the program does nothing yet, it just logs on and reports session-stats. By reporting the ora_sess_info 3 times, I get an idea of how much overhead each step is. Mind that I have already optimised the ora_sess_info to do just 1 (One) RoundTrip and 1 sort.

The result on stdout looks like this:

The timing-info in the log-lines gives us the approximate times for each step. 

Notice that "logon", e.g. opening a connection (in my case thin-mode!) seems to take 3 roundtrips, 10 executes and 4 user-calls. Subsequent call to ora_sess_info () seem to take up 1 roundtrip, 1 execute and 1 user-call each. I did also verify that later by running the 1000s of those calls against a near-silent instance and check in v$sysstats and by running an AWR-report.

So now I know the overhead of my calls (and I put them in comments in the python source-code). In a later version, I might add more to "Measure + Report" information on a connection.

Caveat: Those overheads should be verified for other-versions and future-versions of the driver and of the database. In my case I only use the thin-mode at the moment.

Now the timings: 

For logon, the call to ora_logon() : 2.635146 - 2.485878 = 0.149268 seconds... Say 0.15 sec for an action that we know involves 3 RoundTrips.

The approx time for each call to ora_sess_info() is about 0.05 sec (50 ms...) for what we know involvers 1 RoundTrip.  

First rough indication: a RoundTrip is somewhere below 50ms, and probably much less because each of the calls involves the roundtrips Plus the actual query on the RDBMS, Plus the output to stdout and the overhead of the python-function calls.

How can we measure this better ... ? 

Ping to the Database

The python-oracledb (link) contains a ping function, which is documented to Explicitly do One Round Trip. In the same docu-page, you find the is_healty() function which does Not do a roundtrip, and does perform a full connection check.

I decided to do a test of 3 cases, of 30 seconds each:

1- Running an empty loop to see how much time my python code takes. Count the loops and find time-per-loop.

2- A call to is_healthy() to see how much time that would take (no roundtrip!). Count the loops, and find time-per-call.

3- A call to ping()to generate real real RoundTrip, count the loops and find time-per-RoundTri (and substract the time-per-loop to counter for python-overhead)

The code looked like this:

This function contains 3 while loops that will repeat an action for n_sec and report on the time + time-per-call.

I called the function with n_sec set to 30 seconds.. And the outcome was: 

The time per empty-loop was 0.000314 ms, e.g. less than a single-microsecond of overhead because of the while-loop.

And the avg time for a ping was 1.53 ms. The outcomes of several runs were consistent to 1 or 2 digits (on this system!).

Also check the nr of round trips reported by ora_sess_info () : 15156, which is exactly 3 more than the nr of ping-loops reported. This concurs with the fact that we noticed earlier: logon took 3 RoundTrips. We can conclude that both python (the n_count) and the RDBMS (from v$mystats) reported the same number of RoundTrips happening. And AWR confirmed this separately by reporting a similar number of RT and UserCalls on testing this program.

Confirmed: Each of those ping() calls did 1 RT and 1 UserCall.

The average time for a call to is_healthy() was 0.000680 ms, still less than a microsecond, very short compared to the ping and closer to the "empty loop", hence my impression that this function is efficient but definitely does not do a RoundTrip, e.g. not a complete Health-Check for a connetion (?).

At this point I have an impression that the RoundTrip to the database for this combination of app-platform and location is about 1.5 ms

Wrapping up: Roundtrips  x Latency = Time in the Nework

We can count RoundTrips from V$MYSTAT, V$SESSTAT or by analysing AWR. We have established a way to measure Latency between application and RDBMS from connection.ping(). It was approx 1.5ms on this system.

Once we have these numbers, we can start guesstimating the impact of network-changes or application-moves. 

A program that needs 1000 roundtrips to do its job, in a system with latency of 2ms, will loose 2 sec of real time just in the network. Any increase in Latency.. or a higher nr of RoundTrips will impact time needed by the program. 

By regularly measuring and reporting those numbers, we keep an eye on the impact or our network and the Quality of Service.

Notice that we hardly did any real queries yet. Next blogs will add a few more insights in the traffic between app and RDBMS.

-- -- -- -- -- End of this blogpost, for now -- -- -- -- --

Appendix: Links to scripts.

do_sql_mtrcs.py:  logon + get 1st metrics (.. it can do more, Later)

rt3_ping.py : try to measure the RoundTrips.

ora_login.py : utilities to logon to database and report v$mystats.

prefix.py : utility to prefix print with filename + timestamp to stdout.

.env : edit this file to include your own scott/tiger credentials.

You will also need python components : python-oracledb and dotenv, which you can pip into your system.

-- -- -- -- -- End of this blogpost, for Real -- -- -- -- --