vertica jdbc connection performance issue

daniel_1daniel_1
in General Discussion
system background:
java spring - hibernate
db is vertica 7.0

setup:
several development pc ( windows )
1 pc as webserver ( linux )
1 pc as db server ( linux )

problem:
once we deployed the system in the web server using tomcat, connection to the db server is very slow, it takes about 30 secs to connect and query, but we dont have this issue in our development pc using eclipse tomcat.

what we tried to do:
1. we deployed the system in the db server...and it works fine.
2. created a simple java to connect to the db server
    - if deployed in web server...it takes around 7 secs to connect to vertica db
    - if deployed in db server...works fine.
3. installed mysql in the db server for comparison
    - deployed the system in web server and it works fine. ( to rule our network issue )

we isolated the cause to the DAO getResultList part of the code:
Time: 2014-09-09_16:51:26.156 Class: TestDaoImpl Message: START DAO IMPL
Time: 2014-09-09_16:51:26.163 Class: TestDaoImpl Message: START getCriteriaBuilder
Time: 2014-09-09_16:51:26.163 Class: TestDaoImpl Message: END getCriteriaBuilder
Time: 2014-09-09_16:51:26.163 Class: TestDaoImpl Message: START createQuery
Time: 2014-09-09_16:51:26.165 Class: TestDaoImpl Message: END createQuery
Time: 2014-09-09_16:51:26.165 Class: TestDaoImpl Message: START from
Time: 2014-09-09_16:51:26.165 Class: TestDaoImpl Message: END from
Time: 2014-09-09_16:51:26.166 Class: TestDaoImpl Message: START select
Time: 2014-09-09_16:51:26.166 Class: TestDaoImpl Message: END select
Time: 2014-09-09_16:51:26.166 Class: TestDaoImpl Message: START getResultList
Time: 2014-09-09_16:51:56.216 Class: TestDaoImpl Message: END getResultList
Time: 2014-09-09_16:51:56.216 Class: TestDaoImpl Message: EXIT DAO IMPL

question:
is there a special configuration?
is it a jdbc issue? something we need to set?
why is it slow in web server only?

any help is greatly appreciated.

Thank You


Comments

  • eli_revacheli_revach
    Hi
    From the DAO log its seems like you spending most of  the time of data fetch  and not on the connect method ,  data fetch   can be directly related to network or prefetch  attribute low value .

    Do I miss something ?

  • daniel_1daniel_1
    Hi Eli,

    sorry my post might be confusing

    Time: 2014-09-09_16:51:26.166 Class: TestDaoImpl Message: START getResultList
    Time: 2014-09-09_16:51:56.216 Class: TestDaoImpl Message: END getResultList

    this just means that it is during this time that the actual connection call to vertica db is issued.
    the log 'getResultList' might be misleading...

    Thanks

  • eli_revacheli_revach
    Hi ,
    Its hard to help , you need to share your code , do you able to do so ? 
    Do you try to profile this method , to know in which connection method you spend your time ? 
  • eli_revacheli_revach
    Please check your connection time using vsql utility ,  from the web server , this will help to figure if its jdbc or general connection problem . 
  • daniel_1daniel_1
    Hi Eli,

    we tried using vsql...it is fast....

    here is the sample testing code we used:
    ==================
    import java.sql.Connection;
    import java.sql.DriverManager;
    import java.sql.ResultSet;
    import java.sql.Statement;
    import java.text.DateFormat;
    import java.text.SimpleDateFormat;
    import java.util.Date;

    public class JavaMysql {

            public static void main(String[] args) {
                    DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
                    Date date = new Date();
                    String url = "jdbc:vertica://192.36.253.114:5433/testdb";
                    String driver = "com.vertica.jdbc.Driver";
                    String userName = "dbadmin";
                    String password = "test";
                    try {
                            Class.forName(driver);
                            date.getTime();
                            System.out.println("BEFORE CONNECTION: " + dateFormat.format(date));
                            Connection conn = DriverManager.getConnection(url, userName,
                                            password);
                            date = new Date();
                            date.getTime();
                            System.out.println("AFTER CONNECTION: " + dateFormat.format(date));
                            Statement st = conn.createStatement();
                            date = new Date();
                            date.getTime();
                            System.out.println("BEFORE QUERY: " + dateFormat.format(date));
                            ResultSet res = st
                                            .executeQuery("SELECT * FROM  TTEST WHERE FTEST=1");
                            date = new Date();
                            date.getTime();
                            System.out.println("AFTER QUERY: " + dateFormat.format(date));
                            while (res.next()) {
                                    String username = res.getString("FTEST");
                                    System.out.println(username);
                            }
                            conn.close();
                            date = new Date();
                            date.getTime();
                            System.out.println("AFTER CLOSE: " + dateFormat.format(date));
                    } catch (Exception e) {
                            e.printStackTrace();
                    }
            }

    ==================

    here is the sample result:
        BEFORE CONNECTION: 2014-09-11 10:39:37.993
        AFTER CONNECTION: 2014-09-11 10:39:43.649
        BEFORE QUERY: 2014-09-11 10:39:43.652
        AFTER QUERY: 2014-09-11 10:39:43.679
        00001
        00003
        00005
        00006
        00007
        00002
        99999
        12345
        AFTER CLOSE: 2014-09-11 10:39:43.695
    ===================

    as you can see..connection take around 6 seconds...
    any help is appreciated...

    Thanks


  • eli_revacheli_revach
    Mmm ...
    Check your  vertica.log file for “Connection received:” pattern  and then refer  to the fourth column , this column include the connection sessionId (example - Session:0x7ffb5800e9e0)  , use this sessionId   and try to find  on the load reference lines of it , each line has a timestamp , it may help you to investigate the root cause   .

     

    You can also try to  use an older JDBC  driver I locally use JDBC  driver 6.1.3 without any issues , so it may related to the JDBC  driver  you are using .

    Thanks 

  • daniel_1daniel_1
    Hi Eli,
    Thank you for your reply.

    we tried using the 6.1.3 driver and it still is slow.

    update:
    we isolated the 2 server pc and made a cross cable connection between them...
    ran the test code and it works fine.

    we are now very confused...
    is the issue in our local network?
    we also have a network firewall that both server goes through, does this matter?

    any more suggestion what to do next?

    Thank You
  • Daniel_LeybovicDaniel_Leybovic
    Hi!

    1. May be its a LOAD BALANCER? Is it enabled or disabled?
    2. Can you post vertica.log while you trying to connect with JDBC?
    3. Did you tried connection pooling?
    4. Can you try to load the driver class in the Static Initialization Block?
    com.vertica.jdbc.Driver"); }static{     Class.forName("
     

  • eli_revacheli_revach
    Firewall , can be your issue , try to disable it and run the test .
  • daniel_1daniel_1
    Hi Eli,

    update2:
    isolated the webserver and the dbserver using a HUB.
    this time connection is very slow.

    Thanks
  • eli_revacheli_revach
    Hi I see, but you not provid any vertica log reference , that covering the connection sessionid ( i guid you above about it) . this may provid addtion view that can help to solve your problem.
  • daniel_1daniel_1
    Hi Eli,

    found the vertica.log here are the log portion between webserver and dbserver

    ---------------------------
    2014-09-11 11:04:14.991 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/2705: Connection received: host=192.36.252.102 port=59633 (connCnt 22)

    2014-09-11 11:04:20.002 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/4686: sendAuthRequest: user=dbadmin database=testdb host=192.36.252.102 authType=3

    2014-09-11 11:04:20.005 Init Session:0x7fd0dc0164c0-a000000028cd73 [Txn] <INFO> Begin Txn: a000000028cd73 'check_login_history'

    2014-09-11 11:04:20.005 Init Session:0x7fd0dc0164c0-a000000028cd73 [Txn] <INFO> Rollback Txn: a000000028cd73 'check_login_history'

    2014-09-11 11:04:20.005 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/4686: sendAuthRequest: user=dbadmin database=testdb host=192.36.252.102 authType=0

    2014-09-11 11:04:20.005 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/2703: Connection authenticated: user=dbadmin database=testdb host=192.36.252.102

    2014-09-11 11:04:20.005 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/2609: Client pid: 32443

    2014-09-11 11:04:20.005 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/2608: Client label: jdbc-07.00.0100-e9f22251-5941-4c82-a43d-34d9d95a1034

    2014-09-11 11:04:20.036 Init Session:0x7fd0dc0164c0 [Session] <INFO> [Query] TX:0(localhost.localdoma-16404:0x27fee8) set session autocommit to on

    2014-09-11 11:04:20.049 Init Session:0x7fd0dc0164c0 [Session] <INFO> [PQuery] TX:0(localhost.localdoma-16404:0x27fee8) SELECT * FROM TTEST  WHERE FTEST=1

    2014-09-11 11:04:20.050 Init Session:0x7fd0dc0164c0 [Session] <INFO> [Query] TX:0(localhost.localdoma-16404:0x27fee8) SELECT * FROM TTEST  WHERE FTEST=1

    2014-09-11 11:04:20.051 Init Session:0x7fd0dc0164c0-a000000028cd74 [Txn] <INFO> Begin Txn: a000000028cd74 'SELECT * FROM TTEST  WHERE FTEST=1'

    2014-09-11 11:04:20.058 Init Session:0x7fd0dc0164c0-a000000028cd74 [Txn] <INFO> Starting Commit: Txn: a000000028cd74 'SELECT * FROM TTEST  WHERE FFTEST=1'

    2014-09-11 11:04:20.058 Init Session:0x7fd0dc0164c0 [Txn] <INFO> Commit Complete: Txn: a000000028cd74 at epoch 0x92e

    2014-09-11 11:04:20.088 Init Session:0x7fd0dc0164c0 <LOG> @v_testdb_node0001: 00000/4719: Session localhost.localdoma-16404:0x27fee8 ended; closing connection (connCnt 22)
    ---------------------------

    its slow in the 1st two lines...
    from 'Connection received:' to 'sendAuthRequest'

    Thanks




  • eli_revacheli_revach
    Ok, Now send the same log content when you connect via vsql from the webserver to the db server.
  • daniel_1daniel_1
    Hi Eli,

    here are the log earlier using vsql

    --------------------------------
    2014-09-11 10:36:41.776 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/2705: Connection received: host=192.36.252.102 port=59626 (connCnt 13)

    2014-09-11 10:36:41.776 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/4540: Received SSL negotiation startup packet

    2014-09-11 10:36:41.776 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/4691: Sending SSL negotiation response 'N'

    2014-09-11 10:36:41.778 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/4686: sendAuthRequest: user=dbadmin database=testdb host=192.36.252.102 authType=3

    2014-09-11 10:36:41.778 Init Session:0x7fd0dc015240-a000000028a75d [Txn] <INFO> Begin Txn: a000000028a75d 'check_login_history'

    2014-09-11 10:36:41.778 Init Session:0x7fd0dc015240-a000000028a75d [Txn] <INFO> Rollback Txn: a000000028a75d 'check_login_history'

    2014-09-11 10:36:41.778 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/4686: sendAuthRequest: user=dbadmin database=testdb host=192.36.252.102 authType=0

    2014-09-11 10:36:41.778 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/2703: Connection authenticated: user=dbadmin database=testdb host=192.36.252.102

    2014-09-11 10:36:41.778 Init Session:0x7fd0dc015240 <LOG> @v_testdb_node0001: 00000/2609: Client pid: 32025
    2014-09-11 10:36:55.894 Init Session:0x7fd0dc015240 [Session] <INFO> [Query] TX:0(localhost.localdoma-16404:0x27f846) select * from TTEST;

    2014-09-11 10:36:55.894 Init Session:0x7fd0dc015240-a000000028a763 [Txn] <INFO> Begin Txn: a000000028a763 'select * from TTEST;'
    --------------------------------

    Thanks

  • eli_revacheli_revach
    Hi I see that on jdbc option you have 22 active connection, however in vsql only 13, you sure you share all the story ?
  • daniel_1daniel_1
    Hi,

    update
    we finally found a way to make the connection fast.

    both web server and db server must have a static ip address. ( previous was via dhcp ).
    after setting both with a static ip, the connection was fast.

    does someone know why?

    Thanks in advance

Leave a Comment

BoldItalicStrikethroughOrdered listUnordered list
Format
SpoilerCodeQuote
Heading 2Heading 1
Emoji
:):D:(;):/:o:s:p:'(:|B):#:*<3o:)>:)
Url
Image
Align leftAlign centerAlign rightToggle HTML viewToggle full pageToggle lights
Drop image/file
Home • General DiscussionComment As ...