Question about performance

[pierpaolo1]

I tried to run a simple 'SELECT' on a few fields from Oracle's instantclient with 'set timing on' and got a duration of 00:00:00.01. I then tried the same query from the same machine in Rust (with connection pooling and prepared statement) and got a variable time around 200-250 ms. What is causing this drop in performance? Can I improve the efficiency of the Rust client?

[pierpaolo1]

PS: the same query executed in dBeaver took 3-4ms. This is what I used in Rust: let start = Instant::now(); let rows = match stmt.query(&[&param]) { Ok(q) => q, Err(e) => { let message = format!("Error in query execution: {}\n{}", e, sql); return Err((Se::ServerError, message)); } }; println!("Elapsed: {:?}",start.elapsed());

[kubo]

The following code, which prints one row, took about 500µs - 700µs in my environment. Could you post minimal reproducible example?

use oracle::{Connection, Result};
use std::time::Instant;

fn main() -> Result<()> {
    let username = "odpic";
    let password = "welcome";
    let database = "";
    // TestStrings definition: https://github.com/oracle/odpi/blob/v5.2.0/test/sql/SetupTest.sql#L169-L175
    // Its contents: https://github.com/oracle/odpi/blob/v5.2.0/test/sql/SetupTest.sql#L360-L366
    let sql = "select * from TestStrings where IntCol = :param";
    let param: i32 = 1;

    let conn = Connection::connect(username, password, database)?;
    let mut stmt = conn.statement(sql).build()?;

    let start = Instant::now();
    let rows = stmt.query(&[&param])?;
    for row_result in rows {
        let row = row_result?;
        let int_col: i32 = row.get(0)?;
        let string_col: String = row.get(1)?;
        let raw_col: Vec<u8> = row.get(2)?;
        let fixed_char_col: String = row.get(3)?;
        let nullable_col: Option<String> = row.get(4)?;
        println!(
            "{},{},{:?},{},{:?}",
            int_col, string_col, raw_col, fixed_char_col, nullable_col
        );
    }
    println!("Elapsed: {:?}", start.elapsed());

    Ok(())
}

[kubo]

FIY.

In the previous comment, I wrote stmt.query(&[&param]) because it is in your code fragment. It is better to use stmt.query_as() when the column types are known.

    let rows = stmt.query_as::<(i32, String, Vec<u8>, String, Option<String>)>(&[&param])?;
    for row_result in rows {
        let (int_col, string_col, raw_col, fixed_char_col, nullable_col) = row_result?;
        println!(
            "{},{},{:?},{},{:?}",
            int_col, string_col, raw_col, fixed_char_col, nullable_col
        );
    }

[pierpaolo1]

Thank you Kubo, sure I can, but I must semplify it because I am in a warp web service and I need async and Arc. First I have a function that get a pool of connections:

pub fn get_pool<'a>(...some arguments here) -> Result<Pool> {
.... extract user, password and service from a configuration file and ...
Ok(PoolBuilder::new(user, password, service)
        .max_connections(2)
        .min_connections(2)
        .build()?)
}

then I call a function that gets the row

pub fn get_myws(param: String, pool:Arc<Pool>)-> error_codes::StatusResult<(String,Se)>  {
    let conn = match pool.get() {
        Ok(c) => c,
        Err(e) => {
            let message = format!("Can't connect to db: {}", e);
            return Err((Se::ServerError, message));
        }
    };
    let sql = "select  aaa, bbb, ccc, ddd  from mytable where (eee = :1)";
    let mut stmt = match conn.statement(sql).build() {
        Ok(s) => s,
        Err(e) => {
            let message = format!("Statement preparation failed: {}", e);
            return Err((Se::ServerError, message));
        }
    };
    //let start = Instant::now();
    let rows = match stmt.query(&[&param]) {
        Ok(q) => q,
        Err(e) => {
            let message = format!("Query execution error: {}\n{}", e, sql);
            return Err((Se::ServerError, message));
        }
    };
    //println!("Elapsed: {:?}",start.elapsed());
... and then continue, but the slow row is the above.

The query works and I can use the extracted values to populate the WS response without any issues. What I'm wondering is why it takes so long to get the response (as you see, I'm calculating only the time needed to submit the query and retrieve the row). The time evaluation is relative to submitting the same query with sqlplus or dBeaver, and the difference is significant (a lot of times slower with Rust). To eliminate other variables, I am naturally using the same machine on the same network and performing the tests at the same time of day, repeating them multiple times.

[pierpaolo1]

Here's a highly simplified example that leads to the same problem. I had to mask the query for privacy reasons (I handle personal data), but it is a simple select. Below, the same query is executed in dBeaver.

// Oracle db
use oracle::pool::PoolBuilder;
use std::time::Instant;
fn main() {
    let user = "myuser";
    let password = "mypassword";
    let service = "MYSERVICE";
    let pool = PoolBuilder::new(user, password, service)
        .max_connections(2)
        .min_connections(2)
        .build().unwrap();
    let conn = pool.get().unwrap();
    let sql = "select  AAA, BBB, CCC, DDD  from MYTABLE where (EEE = :1)";
    let mut stmt = conn.statement(sql).build().unwrap();
    let param = "ABCDEF1234567";
    let start = Instant::now();
    let _rows = stmt.query(&[&param]).unwrap();
    println!("Elapsed: {:?}",start.elapsed());
    let _endc = conn.close();
}

pierpaolo@ufficio:~/rust_projects/test-oracle$ cargo run
   Compiling test-oracle v0.1.0 (/home/pierpaolo/rust_projects/test-oracle)
    Finished dev [unoptimized + debuginfo] target(s) in 0.28s
     Running `target/debug/test-oracle`
Elapsed: 381.025516ms
pierpaolo@ufficio:~/rust_projects/test-oracle$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/test-oracle`
Elapsed: 390.028154ms
pierpaolo@ufficio:~/rust_projects/test-oracle$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/test-oracle`
Elapsed: 382.433002ms

And now dBeaver:

And last a script like this:

time $ORACLE_HOME/bin/sqlplus -s /nolog << EOF
CONNECT myuser/mypassword@MYSERVICE
select  AAA, BBB, CCC, DDD  from MYTABLE where (EEE = 'ABCDEF1234567');
EOF

Result:

real    0m0,155s
user    0m0,032s
sys 0m0,017s

[kubo]

Could you post the table definition and the environment information?

I created MYTABLE and inserted 10000 rows as follows.

SQL> create table MYTABLE (AAA varchar2(30), BBB varchar2(30), CCC varchar2(30), DDD varchar2(30), EEE varchar2(30));

Table created.

SQL> insert into mytable select lpad(level, 10, 'A'), lpad(level, 10, 'B'), lpad(level, 10, 'C'), lpad(level, 10, 'D'), lpad(level, 10, 'E') from dual connect by level <= 10000;

10000 rows created.

SQL> commit;

Commit complete.

Then I ran your example in https://github.com/kubo/rust-oracle/issues/86#issuecomment-2162325784 with changing user, password, service and param. It took 35ms at first time and about 2ms after that.

kubo@minipc:~/issue-86$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.04s
     Running `target/debug/issue-86`
Elapsed: 35.693646ms
kubo@minipc:~/issue-86$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/issue-86`
Elapsed: 2.312832ms
kubo@minipc:~/issue-86$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/issue-86`
Elapsed: 1.629286ms
kubo@minipc:~/issue-86$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/issue-86`
Elapsed: 1.724069ms
kubo@minipc:~/issue-86$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/issue-86`
Elapsed: 2.161777ms

My environment is:

• client: Oracle instantclient 23.4.0.0.0 on Linux PC (Ubuntu 22.04 x86_64)
• server: Oracle Database 23c Free container image (version 23.3.0.23.09) in the client PC

[pierpaolo1]

Thank you, I need to check my company's database settings with the DBAs. I will be able to do this next week. What I understand so far is that each operation takes a considerable amount of time and probably depends on the network. In the meantime, thank you again for the time you've dedicated to me.

[pierpaolo1]

I finally figured out where the problem is: if I pass the parameter to the query with :1 (prepared statement), I get response times around 100-200 ms, but if I concatenate the parameter directly into the query string and pass it as is, I get response times around 5-10 ms, so about 20 times lower. Is this behavior normal? Do you think there's anything I can do to improve the efficiency of the prepared statement? Thank you.

[kubo]

I guess that Oracle creates better execution plan when not using bind variables in your case as https://stackoverflow.com/questions/37005847/oracle-explain-plan-differs-when-using-bind-variables.

If so, you can reproduce it on sqlplus by using variable command. (dBeaver is unavailable to reproduce it because real bind variables are not supported by the tool. See https://github.com/dbeaver/dbeaver/issues/15310)

time $ORACLE_HOME/bin/sqlplus -s /nolog << EOF
CONNECT myuser/mypassword@MYSERVICE
variable param varchar2(30)
exec :param := 'ABCDEF1234567'
select  AAA, BBB, CCC, DDD  from MYTABLE where (EEE = :param);
EOF

Could you ask to your DBA to check whether the execution plans are same or different?

[pierpaolo1]

I think the problem is not with the prepared statement itself. For example, this excerpt, where an Oracle type defined as CREATE OR REPLACE TYPE MY.STRING_ARR_TYPE AS VARRAY(999) OF VARCHAR2(128); is populated with one or more strings, executes very quickly

let sql = "SELECT AAA,BBB FROM CCC WHERE AAA IN (select * from table(:1))";

 let mut stmt = match conn.statement(&sql).build() {

...

}

let arrtype = conn.object_type("STRING_ARR_TYPE").unwrap();

let mut obj = arrtype.new_collection().unwrap();

for m in AAA_COLL {

        let _ = obj.push(m);

    };

let rows = match stmt.query(&[&obj]){

....

while this one, where one of the same strings is passed as a parameter

let sql = "SELECT AAA, BBB FROM CCC WHERE AAA = :1 ";

let mut stmt = match conn.statement(sql).build() {

...

}

let rows = match stmt.query_as::<String>(&[&param1]) {

...

is at least 10 times slower. In both cases, the statement is built before submitting the query; perhaps in the first case, Oracle knows how much space to allocate for the variables, but I don't know how to do the same for a single string.

[kubo]

The two cases in the previous comment execute different SQL statements with different parameter types. So no wonder the execution plans are different and one is slower than the other.

Have you checked the sqlplus commend in https://github.com/kubo/rust-oracle/issues/86#issuecomment-2255956900?

[kubo]

I recommend you to check execution plans. I guess that Oracle optimizer chooses index scan when parameters are embedded as literals in the SQL statement. On the other hand it chooses full scan when parameters are passed as bind variables such as :1. Full scan is slower than index scan generally.

If the issue is reproduced by sqlplus commend as noted at https://github.com/kubo/rust-oracle/issues/86#issuecomment-2255956900, you can check the execution plan by the following commands.

$ sqlplus myuser/mypassword@MYSERVICE
SQL> explain plan for select  AAA, BBB, CCC, DDD  from MYTABLE where (EEE = 'ABCDEF1234567');
SQL> select * from table(dbms_xplan.display());
SQL> variable param varchar2(30)
SQL> exec :param := 'ABCDEF1234567'
SQL> explain plan for select  AAA, BBB, CCC, DDD  from MYTABLE where (EEE = :param);
SQL> select * from table(dbms_xplan.display());

If not, you need to ask your DBA or make a program which executesexplain plan for select-statement and then select * from table(dbms_xplan.display()).