Oracle23ai and python - too many RoundTrips, Fixed.

 TL;DR: Time got lost due to leftover code. In our case, some well-intended "defensive coding" caused additional RoundTrips and some commit-wait time.

Found it. Fixed it.

And at the same time, we (re)learned a little about coding, and on how to measure, and how to "instrument" our code.

Image: waiting for a train. I've spent a lot of time waiting for trains, waiting for planes, and waiting for traffic jams..

Background: Suspiciously slow python code.

After some careful testing we stumbled across parts of the program that did more RoundTrips than the data justified. And RoundTrips were still the item that seemed to cause us most "wait-time".

Testing: Run the suspicious code in "isolated" test.

To better observe, we re-worked the UnitTest to run just the parts of the code that we suspected to cause "slowness". After much simplification, we ended up with this result:

We see the result of 1000 loops of "insert item". That took 14.17 seconds, corresponding to a "speed" of 70.58 records/sec.

From the session info (V$MYSTATS) we see that the session did about 1000 executes, which makes sense for 1000 inserted records.

But the surprising numbers are the RoundTrips and the user-calls: 3000 each ??

It seems this code does 3 Roundtrips for every record inserted....

We also know that this particular setup at the time had a latency of around 3-4ms per RT. Meaning that 3000 RTs would consume close to 12sec of the 14sec elapsed.

Furthermore, from V$MYSTAT, we notice that the RDBMS consumed 160 Centiseconds, or 1.6 sec of time.

Note1: The db-connect and the measurement-queries represent the additional overhead of 14 executes, 4 roundtrips and 5 user-calls. We know this from earlier testing of similar code, see previous blogs (link). 

Note2: I also realise the reading or our stdout takes some getting used to, we sometimes appear a little "over instrumented". My bad. But it Helped!

Note3: the DB-time for the session is reported at 160 CentiSeconds e.g. this session only consumed 1.5 second of time at the RDBMS. The rest of the elapsed 14 sec is spent "elsewhere", and we suspect 12sec of that were spent in RTs ... Interesting? Something for later research?

Anyway, from this test, it seems the insert of these particular item-records contains some overhead. Time to read the code...

Code Inspection: Aha.

Once we had the suspect isolated as "inserting of items", we examined the code involved. And after some searching, the simplified version of what we found was this:

There are two things "wrong" with this code.

Firstly, the Try-Except block. It will catch parse-errors. But after catching the exception, it does not really know "what to do with the error". It simply re-raises it and then quits. You can smile at "return 0" as well.. 

But what mattered in our case: the parse-attempt causes a RoundTrip to the RDBMS (and RTs are considered Evil, in our case).

Secondly, there is a Commit after the insert. Oops. Transaction-Logic was not supposed to be part of the "insert function". That commit was a leftover from the "development time", when commits were useful to preserve the state (the data) that would otherwise get lost if the program did an exit-on-error.

But guess what: a commit causes a RoundTrip (and RTs are considered Evil, in our case).

Note: The developer was Innocent: he had created this code with the Best Intentions. There was a reason for putting the parse and print-of-stmnt there.  On errors, I will _Always_ ask for the offending SQL. And over time, as the datamodel evolved, columns were added/modified, causing statements to fail. Hence the need to "print the SQL".

Please understand that I don't want to unfairly blame the DEV...

The improved version.

It was not difficult to remove the offending code. And after some edit, we ended up with this (simplified!) version:

Now the function only does the insert, and returns the newly-found ID. Parse and Commit have been removed. This should avoid some round trips. 

Will this speed up our (test)code ? Let's run it... 

And Voila, the same 1000 inserts now done in 4.46 seconds, and with now only 1000 Round-Trips. Since on this setup we know that an RT is generally about 4ms, the timing-info make sense: We eliminated 2000 RTs, and at 4ms per RT that would make the program run about 8sec faster from eliminating RTs alone... 

And especially from a "far-away" application with vey high numbers of inserts, this is going to make a difference.

But there is more: The reported DB-time from V$MYSTAT is now down to just 14 CentiSeconds. That might be "explained" from the 1000 commits of the previous version of the code. A commit would realistically (on this old test-system) take about 1ms. Interesting.

The parse-time we save by no-parsing is likely to be minimal: re-parsing the same statement is a Very Efficient operations thx to the Oracle Shared_Pool.

The total gains from the new code seems to be about 10sec: 8sec gained from eleminating RTs, and 1.4 sec gained at the DB-time, probably from eliminating Commits. Total gain close to 10 sec. And that concurs with the measurement.

In summary: The new reported "speed" is now 224 records/sec.

About 3x faster.

Wrap-up, on the (Human-) Coding-side.. 

The  Defensive Coding is generally not a bad thing and the "problem-code" was built with the Best Intentions.

The parse-call was intended to check the connection, check the privs, and check the syntax of the statement. And "defensive coding" is generally not a bad thing. Except that sometimes, the addition of "being careful" results in time spent on un-necessary activity. These "checks" were better done in the Testing-phase, or ultimately by single-calls at the start of the program. Not inside of a high-frequency call.

Key points: 

Spend more time informing DEVs.

Pay attention to (Unit-)Testing, maybe include reporting of statistics and time ? 

Do occasional code-reviews ?

Wrap up, on the (geek-tech) Measurement-side:

We have the start of instrumentation: python does some time-keeping and prints timestamps.  And the captured data from V$MYSTAT helped to identify the additional RoundTrips and user-calls. We also noted the DB-time: after removing parse- and commit- overhead, there is Notably less time reported as DB-time.

It would be nice to know a little more on the "time spent" by the various componentsin more detail... 

Future improvements come to mind : better use of the timing-information available in python (time.perf_counter/ns ? ). And what about the data available in Oracle (the new sys_time_model?). Maybe also use the linux time command?

Would it be possible to "measure" time on both sides: application + RDBMS, and then attribute the "missing time" to RoundTrips ?  Future Blog(s).. ? 

Key point: 

Improve on Instrumentation ?

(spoiler: possibly more ideas on instrumentation coming... )

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

Appendix: links to code..

tst_merge_src.sql : set up the tables for this test (re-used from previous test)

tst_ins_item.py : the test-code used in the demo

Plus these additional files, needed to import helper functions into test-program:

ora_login.py :  login and some other oracle-helper functions.

duration.py : time-keeping and reporting functions - instrumentation

prefix.py : print the filename + timestamp to stdout - instrumentation.

.env : to replace credentials with your own scott/tiger@host:port:service

And you may need to get (pip3) the following:

pip3 oracledb   

pip3 dotenv

pip3 datetime

pip3 array

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

Oracle23ai and python - How to fix (avoid) a MERGE statement.

TL;DR: Still using Oracle and python, and loving the combination. But some Annoying High-Frequency MERGE statements from several python programs caused too many RoundTrips... Trying to fix that.

And can I just say: RoundTrips are Evil !

Image: Vaguely related, we have lots of Traffic, and we are trying to MERGE...

Background: need to Eliminate RoundTrips.

For a number of python programs we have logic that checks on "existing data". One example is to find a certain SOURCE. The table holding the sources looks like this (simplified):

If a source-record, by whatever SRC_NAME, exists, we want to get the ID, and if the source does not exist, we need to create it and return its newly assigned ID. 

Perfect case for a MERGE-statement, righ ?

Except that we do many source-checks per second, and each of those stmnts becomes a RoundTrip. These merge-stmnts were 2nd on our high-frequency-list. And since we eliminated the single-record-inserts, they are now Top-of-Problem-List.

The Problem (simplified): 

The function will check for existence of a source-record. The MERGE statement was the most obvious to use here. Our MERGE statement looked like this (somewhat simplified):

The MERGE stmnt is quite standard: check for existence of a given name, and it it doesnt not exist: create it. Then return the ID.

Also notice the (global) variable: src_dict = {}, it will hold the pairs of SRC_NAME and ID as we find them.

The function that uses this MERGE statement gets called at very high frequency in several places. And in the original situation, every call causes a round-trip to the RDBMS.

The original function (simplified) looks like this:

Quite straight forward: create a cursor, assign the bind-variables, execute the statement, and catch the returned ID. Job Done. Except that this would sometimes run at 100s per sec. and show millions of executes per hour in AWR.

Note that we effectively check for parent-records or LOV-records before an insert of a detail-record. I can imagine other constructs, such as triggers or a PL/SQL function to contain this logic. But here we are...

Note Also: On the topic of MERGE-stmnt, allow me a sidestep to this blog by Oren Nakdimon about concurrency-issue with MERGE (link), but that is out of scope for me at this point. Maybe Later.

The Possible Solution:

Thinking back to my previous "Fix for Roundtrips" (link), some form of local buffering or a "local cache" would seem appropriate. But there were some issues:

- Uniqueness: Any new record, e.g. newly-found SRC_NAME, should Ideally be "claimed" with a new ID into the RDBMS Immediately to prevent other systems from assigning different IDs to the same source-name.

- Timeliness: A local buffer would _always_ be out of date, especially when multiple running jobs were likely to discover the same or similar sources in the same timespan. Ideally, the local buffer would always have to be up-to-date, or kept in sync, with the Database.

In short: The Truth is In the Database, the Single Point of Truth (SPOT, classic problem of copy-to-cache...).

- And preferably no "Slurp" of all data: A local buffer could potentially be large, but not every program-run needs all the records. Most programs would only need a small set of the data, typically 10-20 source-records (but they do millions of unnecessary merge-check-retrieve for that small set of SRC_NAMEs). A pro-active "Slurp" of a large set of LOV-data would not be desirable.

One of the "lucky" aspects of our merge-problem was that the SOURCE-data, for this process, was insert/lookup-only. Any updates (comments, modifications, or even combining of sources) would happen elsewhere. The "worker programs" just needed to fetch an ID, or create an ID where none existed yet. 

But any new ID would have to be "immediately" stored into the RDBMS to have it available for others.

The concept-solution.

With some thought, the following pseudo-code came to mind (some architects will call this a "design pattern"):

The comments speak for itself. I chose a python structure called a DICT, which I think is similar to an associative-arry in PL/SQL. 

Note that at this point of writing, I do not yet know if that choice was "optimal", but it seemed to work just fine in our cases. Again something to investigate Later...

Let's put it to Code.

This idea was relatively easy to code. A link to complete and hopefully runnable setup- and test-scripts is at the end of the blog.

The new function First checks if the SRC_NAME is present in a DICT, and if not, then calls the "old function" to check against the RDBMS.  Then returns the ID.

It looks like this:

That was Easy enough (In practice there is a bit more, but out of scope). And it also seemed to pass all of my testing. 

But was it really Better...?

Now Race it for Speed....

To find if something is "faster". I tend to just call the thing 100s or even millions of times, and compare timings.

Our test-case is best described as: 

- The potential names are "src_123", using numbers from 1-1000.

- At the start, the table contains 501 records with SRC_NAMEs and IDs ( the odd numbers. Setup is via the file tst_merge_src.sql (links to all files below)

- Program will generate names randomly of format "src_123". Then check the name, and add a new record if needed.

- We run this for 100-random-names and report timing + statistics... We check the timings, and repeat for another 100-random-names. Until Control-C.

The Original Function with Merge: 200 records/sec, steady.

Here is the first run of 100 checks, using the old function.

The top-right terminal shows stdout of the test-program: 

It did 106 RoundTrips to test 100 records (100 merges plus 6 to connect and some overhead). It managed to do this at a rate of 212 records/sec. Check also the time-difference of the two lines at start (blue mark): the test took about 0.5 of a sec for 100 records, which confirms: 200/sec.

To the Left, we see a terminal with the count of the records: At the start of the test, there were only the 500 + 1 existing old sources. After the first pass of 100 records, the random-mechanims found 51 (even numbered) new names and merged them into the table. Those newly-found names are immediately "claimed" with an ID. Any other program finding the same names, would be able to pick them up and use the Correct ID.

Let's hit enter a few times and do some tests. After 6 runs:

Now the program did 621 RTs (600 records checked, and some overhead for commit and statistics. But the speed is still 180/sec. In fact, it varied a little, but the rate was stable around 200 records/sec.

Meanwhile, the record-count now shows 223 new records added (e.g. 223 new names found + merged). And this program will keep processing at this rate.

 The Speed is 200 records/sec, no matter how long we run test.

Time to hit Control-C and start testing the new function...

The New Function: using a DICT with cached values..

On the first run with the new function we found the same speed:

No improvement yet. It added 100 RTs and was still only processing at 200/sec. 

But the DICT now contains 97 elements, this is the start of our "cache"... 

The record-count showed the total of NEW records now 257, some 34 records were added in this round.

Let's now hit enter a few more times and get to 10-runs with the new function, and as we run more records, the DICT fills up and the cache-effect starts to work:

Now we have a speed of 500 records/sec and the DICT now contains 637 records (out of a potential maximum of 1000). And the number of RTs per run-of-100 is down to about 30 per testloop.

As we run more+more test-loops of 100 records, most of the 1000 potential names end up in the DICT, the number of RTs needed decreases, and the speed in nr or records/sec goes up steadily...

At the 25th test-loop, the DICT holds 902 values, and per test-of-100 we are down to about 10 RTs. The measured speed has gone up to 1797 records/sec: that is more than 8x faster than the original function.

This Cache-Mechanism Works !

Reflexions... 

The local cache will Not Know about Deletes or Updates. But for most LOV- or parent-table records, deletes are un-likely. And from the nature of this data: the SRC_NAME is not likely to change over time (it is effectively the Alternate-Key).

As always, I do not like to add additional code to a system: There is enough "maintenance" already without me adding smart-tricks... Weigh the benefits carefully in your own situations.

I do not now (yet) how efficient the DICT-lookups are on large(er) sets. But assuming a local operation (inside 1 process) is generally much more efficient than a call-out to a (remote) RDBMS. But still something keep in mind, maybe check in future tests.

I dont rule out that certain DataFrames also solve this problem. I hope they Do. But I'm not yet sufficiently fluent in DataFrames to comment much. Maybe Later.

Alternatives.... Use a Local Database or a file?  Someone suggested to copy relevant LOV-data into a local store, either a SQLite, or some copy-file type of cache. I would hesitate to do this, but it may be an option. This is not uncommon in systems that deploy Microservices.

Summary, Wrap-up.

The caching mechanism worked. 

And again, the (evil) impact of RoundTrips is demonstrated.

(In This Particular system, YMMV!)

By eliminating calls to and from the database, we reduce the workload on the python program and on the database.

The python-program does not have to call / fill / run statements and wait for the returns.. 

This frees up time and resources for other work. => Win.

The RDBMS does no longer get 1000s of "identical- and near-useless" calls anymore, it doesnt not have to use its precious processing power to serve those merges anymore. 

This frees up resources at the RDBMS side for other work too. => Win.

Needless to say, if you have your software distributed around servers or over datacentres at distance, the impact of Latency and RoundTrips is Even Bigger. 

I said it before (+/- 1998): Chattiness is the next Challenge in IT.

-- -- -- -- -- End of this blog, for Now -- -- -- -- --

Appendix A: links to sourcefiles.

tst_merge_src.sql : the test table (from tst_item_labels.sql from earlier blog)

tst_merge_src.py : the testdemo python code. (it needs some imports!)

The program imports the following: os, sys, array, random, time, datetime and dotenv. 

And of course the oracle-driver: python-oracledb.

All of which are either standard in your python-installation, or can be get with pip3.

And I use some helper-files, you'll need those for import:

prefix.py : function pp(*argv), prefix the stdout lines with file + timestamp

duration.py : the stopwatch-utility I use.

ora_logon.py : functions to logon to database, and to report data from v$mystat

.env : edit this to include your scott/tiger@orcl, dotenv will read it.

-- -- -- -- -- End of this blog, for Real -- -- -- -- -- 

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 -- -- -- -- --