Data … as usual

All things about data by Laurent Leturgez

Category Archives: java

Playing with Python and Machine Learning in the Cloud … for Free

Leave a comment Posted by on April 16, 2019

If you are interested by the Python language and Machine learning programming (which is usually linked), you will probably think about configuring an environment on your laptop or instantiate an environment hosted by a Cloud provider, which is a bit expensive especially if you want doing some very basic tests.

If you want to try (and build) those very trendy neural networks, you will need a GPU to speed up your programs (and some related boring stuff like installing and configuring Cuda etc.). Same thing if you want to play with spark (and specifically with pyspark)

That can be a boring stuff to do. But do you know that it’s possible to quickly set up an environment in the cloud for free … yes for free. So let’s have a look to two solutions : Google colaboratory (named colab) and Kaggle.

But before we start, we need to know what a notebook is, because these platforms use python notebook as playground.

What is a notebook ?

A notebook is a file which embed code, markup language (HTML) and equations. Each notebook is divided by cells and each cell can be executed individually inside a kernel.

When the code is python, the file extension is usually ipynb. Please note, that notebooks can run other languages than python, each kernel run a specific language for example, Python or Scala.

If you want to know more about notebook, follow these links: https://jupyter.org/ or https://en.wikipedia.org/wiki/Notebook_interface.

 

Google Colaboratory (Colab notebooks)

Google colab is a free notebook environment hosted by Google. To access it, you only need a free google account. Once you created your notebook, you have the possibility to save it on a Google drive file (with ipynb extension) and, optionally, export it on github.

To create your first notebook, you have to go to https://colab.research.google.com/notebooks/welcome.ipynb and then click the “File” Menu and Select “new Python 3 notebook” (or New Python 2 Notebook, if you want to deal with python 2).

Colaboratory Notebook 1

This will create a new folder in your google drive home root directory named “Colab Notebooks” with the file you created in it.

 

Once in your notebook, you can add some cells and write your first python lines.

But, what you have to know is that you are in a remote environment with packages installed (by default you have many python packages already installed), and once instantiated, you can even modify your kernel by installing new softwares etc.

For example, let’s say … we want to set up a pyspark environment. We first need to install pyspark with pip and then run a bunch of pyspark code to test everything is ok.

The notebook is available at this URL (I saved it on github): https://github.com/lolo115/python/blob/master/notebooks/google_colab/blog/pyspark1.ipynb, and the result is represented below:

 

Colaboratory Notebook 2

You can even load files from your local disk to your runtime, and then run code on it. In the example given below (and integrated in the notebook linked above), I used the google API to do that:

Colaboratory notebook 3

Of course, this environment is for testing purpose only, you don’t have a lot of power behind but it’s useful if you want to start learning Python, or test a bunch of script without any local infrastructure and … it’s free.

Kaggle

The second platform to start playing python is more machine learning oriented. Indeed kaggle is a platform for data scientists who are allowed to share and find some data sets, build model, enter in datascience challenges etc.

Accessing to kaggle is free, you just have to subscribe at www.kaggle.com and then log in.

Once logged into the system, you have to go to www.kaggle.com/kernels and click on “New Kernel” and select your preferred style, and you will have access to a notebook with default packages loaded (like numpy and pandas) :

Kaggle

Basically, kaggle is not very different from Google Colaboratory … but kaggle is interesting because you can enable a GPU for your notebook.

To do that, you can go to the “settings” area (in the bottom right corner) and set “GPU” to “ON”.

Kaggle

This will enable a GPU (ok it’s not a farm 😉 ) but this can help you to work on small workload and why not on a small neural network.

Below, a small bunch of code that use tensorflow and gives you the information about GPU enablement.

 

Please note that you can easily upload your datasets (or use datasets provided by kaggle) by clicking on the “+ Add Dataset” Button

That’s it for today 😉

 

Advertisement
Cloud, Development, java, Machine Learning, Python, Spark

Insert data in Oracle with Java … Batched mode.

1 Comment Posted by on January 19, 2018

Problem / Context

Today, I worked on a performance issue at my customer. The context is a Java app which did a processing and at the end of this processing, the application inserts tons of data on an Oracle database.

The customers was complaining about slow performance on the insertion phase and asked me to have a look on it.

Database was IO Bound, and many sessions were doing some one-row inserts on various tables (INSERT INTO … VALUES (:1, :2, …) ). These one-row insert were off course processed many times, and oracle session’s stats was reporting a high number of executions.

On the Java side

As an Oracle DBA or Developer, we all know that, with PLSQL, it’s easy to write a FORALL loop that will bulk insert the data, and then reduce execution time. To do that, you need to have a cursor which is read in bulkl (BULK COLLECT) and each part is then inserted in the database. This reduces the number of operations, loops etc.


DECLARE
CURSOR s_cur IS
SELECT *
FROM servers;

TYPE fetch_array IS TABLE OF s_cur%ROWTYPE;
s_array fetch_array;
BEGIN
OPEN s_cur;
LOOP
FETCH s_cur BULK COLLECT INTO s_array LIMIT 1000;

FORALL i IN 1..s_array.COUNT
INSERT INTO servers2 VALUES s_array(i);

EXIT WHEN s_cur%NOTFOUND;
END LOOP;
CLOSE s_cur;
COMMIT;
END;
/

Source: http://psoug.org/snippet/FORALL-Insert_499.htm

In Java, the problem can be different because the data processed by your app are not necesseraly coming from a database.

Usually, statements are prepared, variables are attached and the statement is executed. When it’s done in a loop, it looks something like that:


try{
         DriverManager.registerDriver (new oracle.jdbc.driver.OracleDriver());
         Connection c = DriverManager.getConnection ("jdbc:oracle:thin:@192.168.99.8:1521:orcl","laurent","laurent");
         PreparedStatement stmt = c.prepareStatement("insert into emp(employee_id,first_name,last_name,salary) values (?,?,?,?)");
         start=System.currentTimeMillis();

         for (int i=0 ; i < 50000 ; i++) {
                  stmt.setInt(1,i);
                  stmt.setString(2,generateRandomChars("01234567890ABCDEF",16));
                  stmt.setString(3,generateRandomChars("01234567890ABCDEF",16));
                  stmt.setInt(4,r.nextInt(10000+1)+5000);
                  stmt.executeUpdate();
         }
         stop=System.currentTimeMillis();
         System.out.println("time = "+(stop-start));
         stmt.close();
         c.close();
   }
   catch(Exception e){
      System.err.println(e);
      e.printStackTrace();
   }

The problem is the statement is sent to the database 50000 times, and then increase number of operation between the database and the application. As a result, execution time is high (this demo has been executed on a VM on my laptop):

[oracle@oel6 JAVA]$ time java -cp $CLASSPATH:ojdbc7.jar:. TestNoBatchedInsert
time = 75430

real    1m16.514s
user    0m5.279s
sys     0m1.080s

As for PLSQL, there is a technique to write a beautiful and powerful java code that will process inserts by batchs, and then reduce the number of loops, calls between database and application etc.

To do that, instead of using executeStatement method X times, we can use the addBatch method that will create a “batch” which will be executed on the database when PreparedStatement’s method “executeBatch” will be called.

If you’re familiar with FORALL in PLSQL, you probably know that, the more the batchsize is big, the more memory you will use. In Java, it will be the same and the result will be a bigger heap size, that’s why it’s recommended to define a batch size and each time your batch will reach a max size, the batch will be executed. This can be done like this:

try{
        DriverManager.registerDriver (new oracle.jdbc.driver.OracleDriver());
        Connection c = DriverManager.getConnection ("jdbc:oracle:thin:@192.168.99.8:1521:orcl","laurent","laurent");
        PreparedStatement stmt = c.prepareStatement("insert into emp(employee_id,first_name,last_name,salary) values (?,?,?,?)");
        start=System.currentTimeMillis();

        int batchSize=5000;
        int count=0;
        for (int i=0 ; i < 50000 ; i++) {
                stmt.setInt(1,i);
                stmt.setString(2,generateRandomChars("01234567890ABCDEF",16));
                stmt.setString(3,generateRandomChars("01234567890ABCDEF",16));
                stmt.setInt(4,r.nextInt(10000+1)+5000);
                stmt.addBatch();

                if (++count % batchSize == 0) {
                        stmt.executeBatch();
                }
        }

        stop=System.currentTimeMillis();
        System.out.println("time = "+(stop-start));
        stmt.close();
        c.close();
}
catch(Exception e){
  System.err.println(e);
  e.printStackTrace();
}

Now, if I run this program, wall time is not really the same scale:

[oracle@oel6 JAVA]$ time java -cp $CLASSPATH:ojdbc7.jar:. TestBatchedInsert
time = 598

real    0m1.964s
user    0m3.393s
sys     0m0.269s

On the database side

AWR Reports show many things:

  • First,  if we run the java sample codes as they are described, the no batch mode will commit the database after each execute update. As a result, log file switch event will increase:

Non batched inserts:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait
Event                                Waits Time (sec)    Avg(ms)   time Class
------------------------------ ----------- ---------- ---------- ------ --------
log file sync                       49,999         64       1.28   86.8 Commit
DB CPU                                            9.3              12.6
db file sequential read                 47          0       0.97     .1 User I/O
SQL*Net message to client           50,012          0       0.00     .1 Network
log file switch completion               1          0      27.60     .0 Configur
undo segment extension                   2          0       5.16     .0 Configur
direct path write                        3          0       1.08     .0 User I/O
direct path sync                         1          0       3.15     .0 User I/O
Disk file operations I/O                19          0       0.04     .0 User I/O
control file sequential read           194          0       0.00     .0 System I

Batched inserts:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait
Event                                Waits Time (sec)    Avg(ms)   time Class
------------------------------ ----------- ---------- ---------- ------ --------
DB CPU                                             .3              72.9
SQL*Net more data from client          268          0       0.17   10.1 Network
log file sync                           13          0       3.29    9.5 Commit
db file sequential read                 49          0       0.37    4.0 User I/O
Disk file operations I/O                17          0       0.03     .1 User I/O
control file sequential read           134          0       0.00     .1 System I
SQL*Net more data to client             10          0       0.02     .1 Network
SQL*Net message to client               22          0       0.00     .0 Network
log file single write                    0          0                .0 System I
asynch descriptor resize                 0          0                .0 Other
  • Then, due to batched process, number of buffer gets is reduced when batched inserts are used

Non batched inserts:

Segments by Logical Reads                   DB/Inst: ORCL/orcl  Snaps: 200-201
-> Total Logical Reads:         212,288
-> Captured Segments account for   28.4% of Total
-> When ** MISSING ** occurs, some of the object attributes may not be available

                     Tablespace
Owner                   Name
-------------------- ----------
                     Subobject  Obj.                             Logical
Object Name            Name     Type        Obj#   Dataobj#        Reads  %Total
-------------------- ---------- ----- ---------- ---------- ------------ -------
LAURENT              USERS
EMP                             TABLE      93857      93860       52,576   24.77

Batched inserts:

Segments by Logical Reads                   DB/Inst: ORCL/orcl  Snaps: 201-202
-> Total Logical Reads:          11,792
-> Captured Segments account for   83.0% of Total
-> When ** MISSING ** occurs, some of the object attributes may not be available

                     Tablespace
Owner                   Name
-------------------- ----------
                     Subobject  Obj.                             Logical
Object Name            Name     Type        Obj#   Dataobj#        Reads  %Total
-------------------- ---------- ----- ---------- ---------- ------------ -------
LAURENT              USERS
EMP                             TABLE      93857      93860        3,504   29.72
  • Same for buffer gets. Execution number is less for batched inserts (number of execution depends on your batch size)

Non batched inserts:

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
    152,587      50,000          3.1   71.9        2.1  11.3     0 7c9ws5uvx9nyc
Module: JDBC Thin Client
insert into emp(employee_id,first_name,last_name,salary) values (:1 ,:2 ,:3 ,:4
)

Batched inserts:

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
      3,669          10        366.9   31.1        0.1    57     0 7c9ws5uvx9nyc
Module: JDBC Thin Client
insert into emp(employee_id,first_name,last_name,salary) values (:1 ,:2 ,:3 ,:4)

 

When developer have to insert tons on data from a java app, it’s better when they used the best way to do it …. batched inserts have to be used in that case, it will help the database to be more powerful.

That’s it for today 😉

11g, 12c, Development, java, Oracle, PL/SQL, tuning

Profiling Java Application with Systemtap

1 Comment Posted by on December 22, 2017

A couple of days ago, I read this tweet from Tanel Poder :

I’m not a JVM internals geek but I was sure there was a way to do the job without restarting the JVM, and I found some cool stuff with Systemtap.

To do this, you have to install two packages on your linux distribution: systemtap and systemtap-runtime-java (and configure correctly your user environment):

[root@spark ~]# yum install systemtap systemtap-runtime-java

Please note that I used a CentOS 7.4 distribution.

Then, and for the demo, I wrote a very small piece of Java that do these steps:

  1. Prints the JVM PID
  2. Wait for a key to be pressed. During this time, you will have to execute the systemtap script I will described later.
  3. Execute a loop ten times, each loop with print a message and wait one second, and this last step is executed in a method name “loop_and_wait”.

Here’s the sample code:


package com.premiseo;

import java.lang.*;
import java.io.BufferedReader;
import java.io.InputStreamReader;
import java.io.IOException;

class Example {
   public static void loop_and_wait(int n) throws InterruptedException{
           System.out.println("Waiting "+n+"ms... Tick");
           Thread.sleep(n);
        }

   public static void main(String[] args) {

      System.out.println("PID = "+java.lang.management.ManagementFactory.getRuntimeMXBean().getName().split("@")[0]);
      System.out.println("Press any key when ready ...");

      try {
        BufferedReader in = new BufferedReader(new InputStreamReader(System.in));
        String next = in.readLine();
      }
      catch (IOException ioe) {
        ioe.printStackTrace();
      }

      try {
        for (int i=0;i<10;i++) {
           loop_and_wait(1000);
        }
      }
      catch (InterruptedException ie) {
        ie.printStackTrace();
      }
   }
}

Then, compile and execute … very basic I said 😉

[spark@spark java]$ javac -cp $CLASSPATH:. com/premiseo/Example.java
[spark@spark java]$ java -cp $CLASSPATH:. com.premiseo.Example
PID = 9928
Press any key when ready ...

Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick
Waiting 1000ms... Tick

Now, to answer to Tanel, I used a short systemtap script that will profile the program and specially the loop_and_wait method. I will count the number of times the loop_and_wait method has been called, and I will account the time spent in this method execution.

To do that, I had to write two probes related to:

  • the full name of the class, including the package name: com.premiseo.Example
  • the class name where the method is defined: Example
  • the method name I want to profile: loop_and_wait

The first one will be executed when the program will start to execute the targeted method (java(“com.premiseo.Example”).class(“Example”).method(“loop_and_wait”)), the second one will be executed when the method will return (java(“com.premiseo.Example”).class(“Example”).method(“loop_and_wait”).return)

The related systemtap script is given below:

#!/usr/bin/env stap

global counter,timespent,t

probe begin {
  printf("Press Ctrl+C to stop profiling\n")
  counter=0
  timespent=0
}

probe java("com.premiseo.Example").class("Example").method("loop_and_wait")
{
  counter++
  t=gettimeofday_ms()
}

probe java("com.premiseo.Example").class("Example").method("loop_and_wait").return
{
  timespent+=gettimeofday_ms()-t
}

probe end {
   printf("Number of calls for loop_and_wait method: %ld \n",    counter)
   printf("Time Spent in method loop_and_wait: %ld msecs \n", timespent)
}

Execution of this systemtap script gave the following result (click the image for full size):

Is it dynamic? Yes, no need to restart the running JVM process you want to target. If you want to target a specific JVM process id, you can use the stap’s “-x” option, add the modify your probe definition like this:

probe java("com.premiseo.Example").class("Example").method("loop_and_wait")
{
  if (pid() == target())
    counter++
    t=gettimeofday_ms()
}

There’s a limitation, you cannot use wilcards in the java probe definition (java(“com.premiseo.Example”).class(“Example”).method(“loop*”) … for example). That would have been useful to profile a set of methods in the same class … but not possible currently.

If you want to read more about this kind of stuff, please read the following websites:

And … that’s all for today !! 😉

 

 

Development, Internals, java, Linux, Oracle, tools

Oracle 12c Application Continuity and its resources usage

3 Comments Posted by on June 1, 2015

During a recent Oracle Meetup in Paris, I met Martin Bach and Bertrand Drouvot. Martin was here to present on Application Continuity, and we had an interesting discussion about this technology. (Bertrand had recently published an interesting post about Application Continuity in a Dataguard configuration … here).

In the post, I will explain quickly how it works based on an sample code I wrote few months ago. I will explained too application continuity resources allocation, where they are consumed, and how much is the resource overhead.

12c Application Continuity … What is it and how does it work?

Application Continuity is a technology that will improve application availability. Before Oracle 12c, Transparent Application Failover (TAF) or Fast Connection Failover (FCF) coud help you to improve application availability without downtime, but developers usually have to implement a TAF or FCF aware code. And usually, it’s wasn’t the case for many reasons (testing and UAT platform which weren’t RAC platform, specifications weren’t written in this aim etc.).

In 12c, Oracle releases application continuity. This technology will do the same thing with more simplicity and has been developed to handle planned and unplanned outages.

Application Continuity works on Oracle 12c database and with application that use:

  • Oracle Weblogic Server
  • Oracle UCP (Unified Connection Pool)
  • Third party JAVA application server which used the PooledConnection Interface
  • JDBC Thin-driver

The lab …

To test application continuity, I wrote a simple test case based on :

  • a 12c (12.1.0.2) RAC Cluster with a container database (CDB), a Pluggable Database (PDB), and a Database Schema (LAURENT) with on 2 tables and a “spy” trigger.
  • a small Java Code sample.

On the database side, I created a TEST table add fill it with 500000 rows, and another one (SPY_TABLE) which will track the id of the TEST table that have been modified :


SQL> create table test as select rownum id, dbms_random.string('U',20) v from dual connect by level <= 500000;

Table created.

SQL> create table spy_table(d date, inst_name varchar2(16), id number);

Table created.

Row updates tracking is made by a trigger on update on the TEST table:


SQL> create or replace trigger spy_test
 2  before update on test for each row
 3  declare
 4    pragma autonomous_transaction;
 5  begin
 6    insert into spy_table values(sysdate,sys_context('USERENV', 'INSTANCE_NAME'), :old.id);
 7  commit;
 8  end;
 9 /

Trigger created.

To make the test, we have to create a RAC service for our database which have these features:

  • FAILOVER_TYPE has to be set on TRANSACTION to enable Application Continuity
  • COMMIT_FAILOVER has to be set to TRUE (Even if it’s a parameter related to Transaction Guard, you have to set it)
  • REPLAY_INITIATION_TIMEOUT, FAILOVER_RETRIES, FAILOVER_DELAY should be reviewed to configure the delays for the replay (see this link for more information)
[oracle@rac1 JAVA]$ srvctl add service -d cdb -s app -preferred cdb1 -available cdb2 -pdb pdb -j SHORT -B SERVICE_TIME -z 30 -w 10 -commit_outcome TRUE -e TRANSACTION -replay_init_time 1800 -retention 86400 -notification TRUE
[oracle@rac1 JAVA]$ srvctl start service -s app -d cdb

[oracle@rac1 JAVA]$ srvctl status service -d cdb
Service app is running on instance(s) cdb1

[oracle@rac1 JAVA]$ /u01/app/12.1.0/grid/bin/crsctl stat res ora.cdb.app.svc -t
--------------------------------------------------------------------------------
Name           Target  State        Server                   State details
--------------------------------------------------------------------------------
Cluster Resources
--------------------------------------------------------------------------------
ora.cdb.app.svc
      1        ONLINE  ONLINE       rac1                     STABLE
--------------------------------------------------------------------------------

Note: I voluntarily configured the service with a preferred node to be sure It will be always the same I will use for my tests (related to resources). But I recommend you to configure it with all instances as “preferred”.

The Java source code is available at this link.

Procedures and functions are:

  • pressAnyKeyToContinue: it’s a private method that make a pause during the program. This pause can be useful to attach a JConsole or VisualVM to track JVM memory and CPU.
  • getStatValue: this function returns the value of an oracle statistics for the current session.
  • doTx: this is the most important function in this program. It will perform the transaction and it’s in this one you will find the most important thing when we code Java with Application Continuity: the callback. This callback is delimited by two calls: beginRequest and endRequest. In this callback, you will put all of the operation you want to protect against failures. If a planned or unplanned outage occurs during the callback, the transaction will be rolled back and then replayed. Please note that in the callback area, you have to:
    • call the prepareStatement function to assign the SQL statement, otherwise you will throw a SQLRecoverableException during the connection failover.
    • disable autoCommit for the connection.
    • put a commit statement to say where the transaction ends.
    private void doTx(Connection c, int numValue) throws SQLException {
        String updsql = "UPDATE test " +
                        "SET v=UPPER(v) " +
                        "WHERE id=?";
        PreparedStatement pstmt = null;

        /* Beginning of the callback
         * AutoCommit has to be disabled in the callback part.
         */
        ((oracle.jdbc.replay.ReplayableConnection)c).beginRequest();
        pstmt=c.prepareStatement(updsql);
        c.setAutoCommit(false);
        for (int i=0;i<numValue;i++) {
            pstmt.setInt(1,i);
            pstmt.executeUpdate();
        }
        c.commit();
        // End of the Callback.
        ((oracle.jdbc.replay.ReplayableConnection)c).endRequest();
        pstmt.close();
    }
  • In the main function, the most important thing is to use the new OracleDataSourceImpl class instead of OracleDataSource.

Then, I compile the code and run it with the number of updates I want to execute in my transaction.

First run

During the run, I execute a “kill -9” against the PMON process of the instance where my java program is connected to:

[oracle@rac1 JAVA]$ ./launchJava.sh SimpleAC 50000
Instance Name = cdb1
Press any key to continue...
Performing transactions

<<<< KILLED THE PMON PROCESS HERE >>>>

Instance Name = cdb2
CPU used by this session = 38643
session pga memory max = 4140696

We can see that, even with an instance failure which was running a transaction (of 50000 updates), the failover occurs without any error message.

The Spy table shows the results above:

SQL> select inst_name,count(*) from spy_table group by inst_name;

INST_NAME	   COUNT(*)
---------------- ----------
cdb2		      50000
cdb1		       1270

This proves that the transaction has been rolled-back and completely replayed after the connection failover.

Mutable values

When a transaction becomes replayable, a problem comes with what we call a mutable value. If you are interested by the definition you can read this on wikipedia: http://en.wikipedia.org/wiki/Immutable_object. But I prefer to explain this in a different way.

Imagine we do a close test to the previous one, but instead of updating data, we insert lines into a table and in this table, we have a timestamp column which takes the value of systimestamp oracle function when we insert a line. Now an outage occurs, the connection if failed over and the transaction is rolled back and replayed on the other node. If we don’t say to Oracle that this value is immutable, the value will be inserted at the timestamp recorded on the second node and not the original one and this could cause some problems in your data integrity.

This problem occurs with sysdate, systimestamp, sequence values and another function that depends on your process id (and other parameters) : SYS_GUID.

If you want to make your variables immutables, you need to have the KEEP grant:


SQL> show user
USER is "SYS"
SQL> grant keep date time to laurent;

Grant succeeded.

SQL> grant keep sysguid to laurent;

Grant succeeded.

SQL> connect laurent/laurent@rac-scan:1521/app
Connected.

SQL> grant keep sequence on seq1 to laurent;

Grant succeeded.

No pain, no gain … what about resources consumption?

Application continuity is a good thing because, with less code modification your java app will become completely fault tolerant. As the documentation mentions, there’s an overhead on CPU and memory … then, let’s check this !

To test this, I used the same environment than previously but I didn’t kill any process, I just ran it with and without callback definition.

Then I measured different things:

  • CPU used by the database session (statistic: CPU used by this session)
  • Memory consumed by the database session (statistic: session pga memory max)
  • CPU used by the java program
  • Memory consumed by the java program (Java heap memory usage)

CPU and memory consumed by the java program has been measured with this good old Jconsole.

To get the java heap memory usage, I set up the program with a heap size of 512Mb as it was the good value to avoid garbage collection during execution.

Here are the results:

  • With callback defined

[oracle@rac1 JAVA]$ egrep 'beginRequest|endRequest' SimpleAC.java
((oracle.jdbc.replay.ReplayableConnection)c).beginRequest();
((oracle.jdbc.replay.ReplayableConnection)c).endRequest();

[oracle@rac1 JAVA]$ ./compile.sh

[oracle@rac1 JAVA]$ ./launchJava.sh -Xms512M -Xmx512M SimpleAC 50000
Instance Name = cdb1
Press any key to continue...
Performing transactions
Instance Name = cdb1
CPU used by this session = 34859
session pga memory max = 3961144

load1_avecCallback

Note the heap memory usage high water mark is 110Mb and the average CPU is 0,4%

  • With no callback defined
[oracle@rac1 JAVA]$ egrep 'beginRequest|endRequest' SimpleAC.java
//((oracle.jdbc.replay.ReplayableConnection)c).beginRequest();
//((oracle.jdbc.replay.ReplayableConnection)c).endRequest();

[oracle@rac1 JAVA]$ ./compile.sh

[oracle@rac1 JAVA]$ ./launchJava.sh -Xms512M -Xmx512M SimpleAC 50000
Instance Name = cdb1
Press any key to continue...
Performing transactions
Instance Name = cdb1
CPU used by this session = 35138
session pga memory max = 3747576

load1_sansCallback

The Heap usage high water mark is 91Mb and the average CPU is 0,2%.

To sum up, we can tell that there is a memory overhead on the jdbc layer (for my example which was based on a transaction of 50000 updates). The CPU overhead announced by Oracle seems to be trivial. On the database side, no overhead has been found on CPU nor on the memory.

If you search more information about Application Continuity, you can read this paper by Oracle : http://www.oracle.com/technetwork/database/database-cloud/private/application-continuity-wp-12c-1966213.pdf

12c, Development, java

Tools to aggregate Oracle CRS logfiles in one file, filter it, sort it, and display it.

9 Comments Posted by on September 11, 2013

If you already faced RAC problems, you had to analyze log files from the entry points which are the alert.log files.

But as Oracle clusterware logs its events in many logfiles (usually one per process), and you have a logfile directory on each server, it can be difficult to detect the causes, and specially the root cause of a specific problem.

Recently I created a little perl script that will help me for this purpose. This script is named “crs_log_aggregator.pl” and is available for download at this URL : https://app.box.com/s/xi3h7bpssrqtkp55q43c.

This script works like this. As input, it takes one or n directories to analyze recursively. Those directories are containing all crs log files of all cluster nodes you want to analyze.

For each directory, it parses each log files (except the alert.log) and each history log files (with file extension: l??). Parsing will get the timestamp mentioned in the read line, if there’s no timestamp (because message is written in many lines for example), the perl script will use the preceding timestamp. (If there were no timestamp for example, in the file header, it will flag the timestamp as ‘N/A’). Every analyzed line in the log file, is completed by its origin represented by the relative file path.

As a result, an analyzed line, is represented in the output file by three parts:

  • the timestamp of the message
  • the origin file of the message
  • the message

As a separator, I used a “<SEP>” tag.

So at this step, each line is recorded in a single unsorted file. If a filter expression has been given to the program as input, which is highly recommended, the filter is applied during the parsing process.

Next, the program will sort the output file by timestamp and will produce a single output file which is now filtered (or not) and this file can be analyzed.

Well, let’s see how it works:

For example, let’s consider a two nodes RAC (hostnames are rac1 and rac2).

As alert.log files are not analyzed, you need to analyze them before to see when the problem occurs.

In my case, I want to analyze 2 days: 2013-05-30 and 2013-05-31.

So first step is to copy is a filesystem, or on your desktop, all the logfiles.

I recommend to put in a single directory all the directories related to a single hostname. Here, I have two directories coming from both cluster nodes ($GRID_HOME/log) :

[oracle@rac1 aggregator]$ tree -d .
.
|-- rac1
|   |-- acfslog
|   |-- acfsrepl
|   |-- acfsreplroot
|   |-- acfssec
|   |-- admin
|   |-- agent
|   |   |-- crsd
|   |   |   |-- oraagent_oracle
|   |   |   |-- orarootagent_root
|   |   |   `-- scriptagent_oracle
|   |   `-- ohasd
|   |       |-- oraagent_oracle
|   |       |-- oracssdagent_root
|   |       |-- oracssdmonitor_root
|   |       `-- orarootagent_root
|   |-- client
|   |-- crflogd
|   |-- crfmond
|   |-- crsd
|   |-- cssd
|   |-- ctssd
|   |-- cvu
|   |   |-- cvulog
|   |   `-- cvutrc
|   |-- diskmon
|   |-- evmd
|   |-- gipcd
|   |-- gnsd
|   |-- gpnpd
|   |-- mdnsd
|   |-- ohasd
|   |-- racg
|   |   |-- racgeut
|   |   |-- racgevtf
|   |   `-- racgmain
|   `-- srvm
`-- rac2
    |-- acfslog
    |-- acfsrepl
    |-- acfsreplroot
    |-- acfssec
    |-- admin
    |-- agent
    |   |-- crsd
    |   |   |-- oraagent_oracle
    |   |   |-- orarootagent_root
    |   |   `-- scriptagent_oracle
    |   `-- ohasd
    |       |-- oraagent_oracle
    |       |-- oracssdagent_root
    |       |-- oracssdmonitor_root
    |       `-- orarootagent_root
    |-- client
    |-- crflogd
    |-- crfmond
    |-- crsd
    |-- cssd
    |-- ctssd
    |-- cvu
    |   |-- cvulog
    |   `-- cvutrc
    |-- diskmon
    |-- evmd
    |-- gipcd
    |-- gnsd
    |-- gpnpd
    |-- mdnsd
    |-- ohasd
    |-- racg
    |   |-- racgeut
    |   |-- racgevtf
    |   `-- racgmain
    `-- srvm

74 directories
[oracle@rac1 aggregator]$ ls -l
total 20
drwxr-xr-x 24 oracle oinstall 4096 Sep 8 14:39 rac1
drwxr-xr-x 24 oracle oinstall 4096 Sep 8 14:00 rac2
If you want some help about this tool, you can use the -h option:
[oracle@rac1 aggregator]$ ./crs_log_aggregator.pl -h

RAC Logs consolidator
---------------------------------------------

Usage

./crs_log_aggregator.pl -c dir1[,dir2,dir3,...,dirN] -o outputfile [-f filter]

[MANDATORY]: -c dir1,dir2,...,dirN
                 comma separated values of source directories to analyze
[MANDATORY]: -o outputfile
                 unique sorted and filtered output file
[OPTIONAL] : -f filter
                 regex filter to apply
[OPTIONAL] : -h
                 print this help

Examples:
$ ./crs_log_aggregator.pl -c data/ -o outfile
         will sort without any filter all log files (*.log, *.l??) recursively found in the data directory. outfile is produced in the current directory as a result.
$ ./crs_log_aggregator.pl -c data/rac1/cssd,data/rac1/crsd -o outfile
         will sort without any filter only the content of data/rac1/cssd,data/rac1/crsd  directories.
$ ./crs_log_aggregator.pl -c data/ -o outfile_filtered -f '2012-10-26|2012-10-27'
         will sort with a filter (regex) that will filter 2 days 2012-10-26 and 2012-10-27.

        more information on perl regex: http://perldoc.perl.org/perlre.html
Next, I will launch the program with the good options:
[oracle@rac1 aggregator]$ ./crs_log_aggregator.pl -c ./rac1,./rac2 -o output_file -f '2013-05-30|2013-05-31'

---------Alert.log : ./rac1/alertrac1.log excluded from analyze

---------Alert.log : ./rac2/alertrac2.log excluded from analyze

[oracle@rac1 aggregator]$ ls -lh output_file
-rw-r--r-- 1 oracle oinstall 243M Sep  8 15:16 output_file
Please note that, if an alert.log file is found, it will be excluded and mentioned in the standard output.
I highly recommend you to use a filter to reduce the amount of data to sort (It can burn lot of CPU and memory). The -f option is use to do this, and takes a regexp style filter (it ‘s used directly in the perl script, so if you are not aware with regexp used in perl script, you can have a look at this URL: http://perldoc.perl.org/perlre.html).
As a result, you have this kind of messages in the output file:
2013-05-31 09:14:59.573<SEP>../rac2/cssd/ocssd.log<SEP> [    CSSD][1111411008]clssgmRPCBroadcast: rpc(0x2a1002a), status(0), sendcount(0), filtered by specific properties:
2013-05-31 09:14:59.573<SEP>../rac2/cssd/ocssd.log<SEP> [    CSSD][1111411008]clssgmFreeRPCIndex: freeing rpc 673
2013-05-31 09:14:59.573<SEP>../rac2/cssd/ocssd.log<SEP> [    CSSD][1111411008]clssgmDeleteGrock: (0x7f3f38637990) grock(EVMDMAIN2) deleted
2013-05-31 09:14:59.576<SEP>../rac1/crfmond/crfmond.log<SEP> [ COMMCRS][1105488192]clsc_connect: (0x7f23b40531f0) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=rac1DBG_LOGD))
2013-05-31 09:14:59.576<SEP>../rac1/crfmond/crfmond.log<SEP> [ default][1083722048]clsdmc_send error code: -7
2013-05-31 09:14:59.576<SEP>../rac1/crfmond/crfmond.log<SEP> [ default][1083722048]Mond is being shutdown by default
2013-05-31 09:14:59.695<SEP>../rac1/agent/ohasd/orarootagent_root/orarootagent_root.l01<SEP> [ USRTHRD][1102350656] {0:0:2} Thread:[DaemonCheck:crf]Daemon Select Thread exiting
2013-05-31 09:14:59.695<SEP>../rac1/agent/ohasd/orarootagent_root/orarootagent_root.l01<SEP> [ USRTHRD][1102350656] {0:0:2} Thread:[DaemonCheck:crf]Skipping Agent Initiated a check action
2013-05-31 09:14:59.695<SEP>../rac1/agent/ohasd/orarootagent_root/orarootagent_root.l01<SEP> [ USRTHRD][1102350656] {0:0:2} Thread:[DaemonCheck:crf]isRunning is reset to false here
2013-05-31 09:15:00.270<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1096657216]sclsctss_gvss1: NTP default config file found
2013-05-31 09:15:00.270<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1096657216]sclsctss_gvss8: Return [0] and NTP status [2].
2013-05-31 09:15:00.270<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1096657216]ctss_check_vendor_sw: Vendor time sync software is detected. status [2].
2013-05-31 09:15:00.314<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1109387584]ctsselect_vermon7: Expecting clssgsevGRPPRIV event. Ignoring 2 event.
2013-05-31 09:15:00.314<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1109387584]ctsselect_vermon7: Expecting clssgsevGRPPRIV event. Ignoring 2 event.
2013-05-31 09:15:00.314<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1109387584]ctsselect_vermon7: Expecting clssgsevGRPPRIV event. Ignoring 3 event.
2013-05-31 09:15:00.314<SEP>../rac2/ctssd/octssd.l01<SEP> [    CTSS][1109387584]ctsselect_vermon7: Expecting clssgsevGRPPRIV event. Ignoring 1 event.
2013-05-31 09:15:00.345<SEP>../rac2/gipcd/gipcd.l04<SEP> [ CLSINET][1093364032] Returning NETDATA: 1 interfaces
2013-05-31 09:15:00.345<SEP>../rac2/gipcd/gipcd.l04<SEP> [ CLSINET][1093364032] # 0 Interface 'eth2',ip='10.10.10.12',mac='08-00-27-92-f1-98',mask='255.255.255.0',net='10.10.10.0',use='cluster_interconnect'
2013-05-31 09:15:00.354<SEP>../rac2/agent/ohasd/orarootagent_root/orarootagent_root.l01<SEP> [ora.crf][1089526080] {0:0:613} [stop] (:CLSN00108:) clsn_agent::stop }
2013-05-31 09:15:00.354<SEP>../rac2/agent/ohasd/orarootagent_root/orarootagent_root.l01<SEP> [    AGFW][1089526080] {0:0:613} Command: stop for resource: ora.crf 1 1 completed with status: SUCCESS

Now, you can analyze the output file directly, but I have developed another app (in Java). This app is available at this URL: https://app.box.com/s/xi3h7bpssrqtkp55q43c.
To launch it, you need to use java 1.7.
This app will show in a more beautiful interface the result of the output file. Messages that are coming from the same file are colored with the same color:
[oracle@rac1 aggregator]$ java -jar Aggr_visualisator.jar
 Aggr_visualisator
Update:
  • in v0.2, I implemented a filter function. This filter is active on the “Message” column.
  • I implemented a colorization function for the “Message” column.
    • if the term “error” is found, the cell will be colored in red
    • If the term “warn” is found, the cell will be colored in orange
    • and if the term “fail” is found, the cell wil be colored in yellow
v0.2 is available at this URL : https://app.box.com/s/xi3h7bpssrqtkp55q43c
two snapshots of this version below 😉
  • Messages colorization:
Aggr_visualisator_0.2_1
  • Filtering messages (based on a regexp)
Aggr_visualisator_0.2_2
If you have any suggestion to improve these tools, send me an email or a comment. I will study them.
I hope this will help you 😉
11g, 12c, Development, java, perl, RAC, tools

← Older posts