1 2 3 Previous Next 30 Replies Latest reply on May 16, 2016 12:20 PM by shawkins

    help needed troubleshooting slow odbc usage

    m.ardito

      Hi all,

      I am trying to debug a very slow odbc connection to teiid: I'm pretty sure it is due to some client factor but I wish to be sure (ie: learn) what can I do on teiid side to debug what/when is happening exactly in teiid as a response from the client query.

      My ideal "test" client is a linux webserver running apache/php  using odbc to get data from teiid.

       

      teiid odbc dsn is like

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

      $ cat ./.odbc.ini

      [teiid_db]

      Description        = PostgreSQL Unicode

      Driver            = /usr/lib/i386-linux-gnu/odbc/psqlodbcw.so

      Trace            = No

      TraceFile        =

      Database        = databasename

      Servername        = 192.168.x.y

      Username        = username

      Password        = password

      Port            = 35432

      Protocol        = 7.4-1

      ServerType         = Postgres

      ReadOnly        = No

      ShowSystemTables    = No

      ShowOidColumn        = No

      FakeOidIndex        = No

      UseServerSidePrepare    =1

      ByteaAsLongVarBinary    =1

      UpdatableCursors    =0

      ConnSettings        =

      Optimizer        =0

      Ksqo            =0

      Debug            =0

      Fetch             = 10000

      UseDeclareFetch        =1

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

       

      I also tested an identical odbc "mysql" dsn on the same server, which connects to a mysql db (the same also used as model in the teiid vdb), but I get very slow results when those results come from the "teiid" odbc dsn.

       

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

      [mysql]

      Driver          = /usr/lib/i386-linux-gnu/odbc/libmyodbc.so

      SERVER          = 192.168.x.y

      PORT            = 3306

      DATABASE        = databasename

      OPTION          = 3

      USER            = username

      PASSWORD        = password

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

       

      I did a few tests, with everything I have at hand:

      - squirrel/win7 on the vdb, via jdbc

      - odbc query tool (ODBC Query Tool download | SourceForge.net) same win7, odbc to teiid

      - php framework (code igniter) with odbc database

      - php, both using odbc_connect and pdo, on linux and windows

      - python with  pypyodbc, on linux and windows

       

      and anywhere, in linux server, odbc/mysql  is much faster than odbc/postgres (to teiid). Even very simple queries need 4-5 seconds to get the response, while mysql odbc is blasing fast...

      selecting more fields from the vdb (or *) only makes thing worse...

       

      On windows, thought, it seems less different (faster). But it's a different everything... so I don't know if it's a good comparison...

       

      I know there are tons of different reasons, for this, and I'm willing to create the best possible setup to spot what is not working well... (and fix it)

       

      So, how can teiid (or the as, or the server where's running, or else) help me in this debug job?

       

      Marco

        • 1. Re: help needed troubleshooting slow odbc usage
          shawkins

          > So, how can teiid (or the as, or the server where's running, or else) help me in this debug job?

           

          Start with the query plan and first ensure that is correct and that JDBC access is giving you the desired performance.

           

          After that you'll want to use the command log and the trace of the org.teiid.ODBC context to get a full picture of the conversation and timing of things between the client and Teiid.

          • 2. Re: help needed troubleshooting slow odbc usage
            m.ardito

            Thanks,

             

            I found that I can see the query plan only for really long queries, if I switch fastly to the request tab of the VDB details, click refresh and hit "plan" button...  but if the request ends, I cannot see it anymore, or the "plan" shows jsut thw word "query", iirc. Works, but it is not very practical, is there any logging method available? Would adding a org.teiid.PLANNER log session work?

             

            I already added

            <logger category="org.teiid.ODBC">

                 <level name="INFO"/>

            </logger>

             

            to standalone-teiid.xml (I see this is reflected in the web console, also) but I never see any trace i the server.log

             

            what levels should I use best for those log sections, WARN, ERROR, DEBUG?

             

            About  my tests:

            My php framework uses odbc tools to query teiid, and I'm using a test web page (which just executes a simple "select x,y form customers where id=z", where z is an integer)

            the URL is like http://test/customers/z Then I reload it to see the results.

             

            When the query works, (with the same or a different "z" id in the query), correct results are displayed. When this happens, if I fastly press F5 to reload the page, usually the query is (slowly) executed again.

             

            But if I wait some seconds, usually then the query fails with errors like

            Message: odbc_exec(): SQL error: [unixODBC]ERROR: TEIID40041 Invalid null Session org.teiid.jdbc.TeiidSQLException: TEIID40041 Invalid null Session; Error while executing the query, SQL state 08S01 in SQLExecDirect

            Message: odbc_exec(): SQL error: [unixODBC]Could not send Query(connection dead); Could not send Query(connection dead), SQL state 08S01 in SQLExecDirect

             

            the above errors are shown many times, pressing F5 in the browser, until, trying enough, the query works again, and was failing for unknown reasons.

            I guess that there could be a connection error, a timeout or else involved, but maybe you can spot something weird or suggest where to look for, in teiid, in  odbc, or in the calling app...?

             

            For comparison, if I simply change the odbc dsn name in the php web app, using an odbc connection to mysql  (which reads the same customer table which is read as model in the teiid vdb)

            it works instanlty and reliably, always. It's like day and night.

             

            Marco

            • 3. Re: help needed troubleshooting slow odbc usage
              shawkins

              > Works, but it is not very practical

               

              You mean in Designer?  It should be able to show the plan even after execution is finished.

               

              From a regular JDBC or ODBC connection you can always just issue

               

              "set showplan on"

              run the query

              "show plan"

               

              Shown on SET Statement | Teiid Documentation and related pages

               

              > is there any logging method available? Would adding a org.teiid.PLANNER log session work?

               

              The plan will be in the logs if trace is enabled for org.teiid.COMMAND_LOG or if showplan is set to the debug level and the INFO level logging is enabled for org.teiid.PLANNER.

               

              > what levels should I use best for those log sections, WARN, ERROR, DEBUG?

               

              For the ODBC traffic trace is needed.

              • 4. Re: help needed troubleshooting slow odbc usage
                m.ardito

                Steven Hawkins ha scritto:

                > Works, but it is not very practical

                You mean in Designer?  It should be able to show the plan even after execution is finished.

                 

                Sorry, no I meant from the web console... I never use Designer, only xml VDBs... it's so much easier for me... it works with nano from ssh...

                 

                Now I stopped the server, enabled ODBC log at TRACE level, restarted the server.

                 

                then I simply loaded my http://test/customers/z test page (z=7496), which has a simple 2 fields select, but is issued by the condeigniter framework orm, which also load the whole model, I guess.

                 

                I loaded the page 2 times, thesecond  a few seconds after getting the first result (no errors) and taking a short look at the server.log.

                 

                The trace (attached, but grepped for "odbc") it seems to show that the first request is handled by odbc in some 11 seconds but also shows a lot (~25) of other queries involving pg_catalog which I don't understand...

                if needed I can provide some detail about the queried table... and also make other specific tests, too.

                 

                The same seems to happen in the second query (simply reloaded the web page) but it takes less (4-5 seconds) and opens a new session, as I can see from the web console, both are still open...

                I expected it to reuse the same... as squirrel and other sql tools do, usually... could this cause worse performances, and could it be due to the way the client works?

                 

                As said I also tested other odbc tools on windows/linux and, iirc, both the times are much better and the same sessions is kept in teiid. But to be more precise I need to do more test, please ask some particular configuration/mdoe if it could help to spot something...

                 

                After writing the above here, now I reloaded the page again, 2 times, and it happened again.

                - first request ~11-12 seconds => new session listed in web console

                - secondo request 4-5 seconds=> new session listed in web console

                 

                now I have 4 sessions alive for 4 requests... of the same identical data form the same web server (client).

                 

                about the query plan I followed your info (thanks) and in squirrel

                 

                for a simple

                select id,rag_soc,pi from ag where id=3

                 

                I get

                 

                AccessNode

                  + Relational Node ID:0

                  + Output Columns:

                    0: id (long)

                    1: rag_soc (string)

                    2: pi (string)

                  + Statistics:

                    0: Node Output Rows: 1

                    1: Node Next Batch Process Time: 1

                    2: Node Cumulative Next Batch Process Time: 1

                    3: Node Cumulative Process Time: 5

                    4: Node Next Batch Calls: 2

                    5: Node Blocks: 1

                  + Cost Estimates:Estimated Node Cardinality: 1.0

                  + Query:SELECT g_0.id AS c_0, g_0.rag_soc AS c_1, g_0.pi AS c_2 FROM apifdbunica.ag AS g_0 WHERE g_0.id = 3 LIMIT 100

                  + Model Name:apifdbunica

                  + Data Bytes Sent:49

                  + Planning Time:1

                 

                Can't spot any problem, by myself.

                 

                Marco

                • 5. Re: help needed troubleshooting slow odbc usage
                  m.ardito

                  For comparison, I executed the "same simple query" from this tool:

                  ODBC Query Tool download | SourceForge.net

                   

                  from my windows machine, and I get instant responses and teiid console show just one session, the same.

                   

                  of course this uses windows odbc pg driver, the same that I previously tested from (eg) msaccess, working ok.

                   

                  you'll find attached logs related to this example.

                   

                  Marco

                  • 6. Re: help needed troubleshooting slow odbc usage
                    shawkins

                    > Sorry, no I meant from the web console... I never use Designer, only xml VDBs... it's so much easier for me... it works with nano from ssh...

                     

                    You may want to log an issue then against web console to make it easier to get the plans - so that you don't have to just get them from the in-flight query.

                     

                    > I expected it to reuse the same... as squirrel and other sql tools do, usually... could this cause worse performances, and could it be due to the way the client works?

                     

                    There is definitely a couple of odd things in the first trace.

                     

                    We see a "SELECT *" being issued - but that is not the entire log as the full query should be shown.  Then the same metadata query is repeated - and it is also looking up oid which means it got that value prior to this but I'm not sure where.  And I don't see the user query anywhere.

                     

                    In trace2 we see the behavior that we would expect - with the user query and subsequent metadata queries.

                     

                    > now I have 4 sessions alive for 4 requests... of the same identical data form the same web server (client).


                    Yes, you do not want that behavior.  There is no obvious error in the trace1 log nor is there a disconnection attempt, so it's hard to say why it's behavior that way.  What configuration options do you have for that odbc client?

                    • 7. Re: help needed troubleshooting slow odbc usage
                      m.ardito
                      > now I have 4 sessions alive for 4 requests... of the same identical data form the same web server (client).

                      Yes, you do not want that behavior.  There is no obvious error in the trace1 log nor is there a disconnection attempt, so it's hard to say why it's behavior that way.  What configuration options do you have for that odbc client?

                       

                      Well, the framework orm supports odbc, and just needs the dsn name, as docs say (https://codeigniter.com/user_guide/database/configuration.html)

                       

                      my config is

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

                      $db['default'] = array(

                              'dsn'   => 'teiid',

                              'hostname' => '',

                              'username' => '',

                              'password' => '',

                              'database' => '',

                              'dbdriver' => 'odbc',

                              'dbprefix' => '',

                              'pconnect' => TRUE,

                              'db_debug' => (ENVIRONMENT !== 'production'),

                              'cache_on' => FALSE,

                              'cachedir' => '',

                              'char_set' => 'utf8',

                              'dbcollat' => 'utf8_general_ci',

                              'swap_pre' => '',

                              'encrypt' => FALSE,

                              'compress' => FALSE,

                              'stricton' => FALSE,

                              'failover' => array(),

                              'save_queries' => TRUE

                      );

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

                       

                      and dsn config is (I'm using both for testing web app access to the same db/table both on odbc/mysql and odbc/teiid)

                      'unica' is a mysql database that is loaded also by apifdb_apimn VDB, along with many (?) other dbs... maybe 15

                       

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

                      cat /etc/odbc.ini

                      [mysql]

                      Driver          = /usr/lib/i386-linux-gnu/odbc/libmyodbc.so

                      SERVER          = a.b.c.d

                      PORT            = 3306

                      DATABASE        = unica

                      OPTION          = 3

                      USER            = user

                      PASSWORD        = pass

                       

                      [teiid]

                      Description     = PostgreSQL Unicode

                      Driver          = /usr/lib/i386-linux-gnu/odbc/psqlodbcw.so

                      Trace           = No

                      TraceFile       =

                      Database        = apifdb_apimn

                      Servername      = x.y.z.w

                      Username        = user

                      Password        = pass

                      Port            = 35432

                      Protocol        = 7.4-1

                      ServerType      = Postgres

                      ReadOnly        = No

                      ShowSystemTables= No

                      ShowOidColumn   = No

                      FakeOidIndex    = No

                      UseServerSidePrepare    =1

                      ByteaAsLongVarBinary    =1

                      UpdatableCursors=0

                      ConnSettings    =

                      Optimizer       =0

                      Ksqo            =0

                      Debug           =0

                      Fetch           = 10000

                      UseDeclareFetch =1

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

                       

                      btw, I notice that yesterday's errors

                       

                      Message: odbc_exec(): SQL error: [unixODBC]ERROR: TEIID40041 Invalid null Session org.teiid.jdbc.TeiidSQLException: TEIID40041 Invalid null Session; Error while executing the query, SQL state 08S01 in SQLExecDirect

                      Message: odbc_exec(): SQL error: [unixODBC]Could not send Query(connection dead); Could not send Query(connection dead), SQL state 08S01 in SQLExecDirect

                       

                      are no more happening today (probably since I restarted the server to apply log settings...)

                      can't imagine what was causing them...

                       

                      Marco

                      • 8. Re: help needed troubleshooting slow odbc usage
                        m.ardito

                        Another test and I'm starting to think that codeigniter is not the cause:

                         

                        I created a very simple php script on the same server but without any framework use: just pure php and odbc

                         

                        here is all the script:

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

                        <?php

                        $dsn="teiid";

                        $connection = odbc_pconnect($dsn, $user, $password);

                        $query_string="SELECT * FROM ag WHERE id=7496";

                        $result=odbc_exec($connection , $query_string);

                        $arr= odbc_fetch_array($result);

                        echo "<li>$dsn";

                        print "<pre>";

                        print_r($arr);

                        print "</pre>";

                        ?>

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

                         

                        this is quite easy to understand I hope.

                        the query still takes 4-5 seconds

                        and the trace is attached: it's too much work for something that simple... and too slow...

                         

                        could it be the linux odbc driver the dsn setup or the odbclinux system itself?

                        but the mysql dsn is 1000 times faster...  also in this simple script.

                        so I guess it's not unixodbc probably?

                         

                        next week I'll test again the same script above on a windows web server on my workstation so to use the same odbc driver & setup as the "odbc query tool" that gave decent speed & trace. It's driving me crazy... it's too different...

                         

                        and btw, again using the teiid dsn, every subsequent query opens a new session...

                         

                        Marco

                        • 9. Re: help needed troubleshooting slow odbc usage
                          shawkins

                          > and the trace is attached: it's too much work for something that simple... and too slow...

                           

                          Essentially your query execution time is defined by:

                           

                          2016-04-01 20:30:07,589 TRACE [org.teiid.ODBC] (NIO3)  invoking server method: executeQuery [BEGIN;declare "SQL_CUR0xb8babc80" scroll cursor with hold for SELECT * FROM ag WHERE id=7496;fetch 10000 in "SQL_CUR0xb8babc80"]

                          2016-04-01 20:30:07,589 DEBUG [org.teiid.ODBC] (NIO3)  Modified Query: START TRANSACTION

                          2016-04-01 20:30:07,589 TRACE [org.teiid.ODBC] (NIO3)  invoking client method: sendUpdateCount [BEGIN, 0]

                          2016-04-01 20:30:07,590 TRACE [org.teiid.ODBC] (NIO3)  invoking client method: setEncoding [UTF8, false]

                          2016-04-01 20:30:07,629 TRACE [org.teiid.ODBC] (Worker263_QueryProcessorQueue96222) g/CoM7JEmCCg invoking client method: sendCommandComplete [DECLARE CURSOR, null]

                          2016-04-01 20:30:07,630 TRACE [org.teiid.ODBC] (Worker263_QueryProcessorQueue96222) g/CoM7JEmCCg invoking client method: sendResults [FETCH, org.teiid.jdbc.ResultSetImpl@665411d7, ..., 10000, true]

                           

                          So approximately 41 milliseconds. 

                           

                          The rest of the non-initialization time is spent repeating setting/releasing a savepoint and executing the same column metadata query at a cost of around 120-200 ms per repetition.  It's not clear from a server perspective or from the pg odbc client code why this is happening.  Can you enable debug logging for the pg odbc client - using the log options from psqlODBC Configuration Options? And which version of the pg odbc client library do you have installed?

                           

                          It would be best if we responded faster to the metadata query - but we're not indexed on oid.  So that may be something that we'll have to look at as well. 

                           

                          The column metadata query and the flag that determines the oid lookup can be seen in http://git.postgresql.org/gitweb/?p=psqlodbc.git;a=blob_plain;f=info.c;hb=HEAD - a debug log would hopefully make it clearer what is happening above there.

                           

                          > and btw, again using the teiid dsn, every subsequent query opens a new session...


                          I'm not sure if we'll have insight into this since it seems like it's above the pg odbc level.

                          • 10. Re: help needed troubleshooting slow odbc usage
                            m.ardito

                            I won't be in office until tuesday, but I tried anyway at home to get some decent test with logging. I have to say that postgres odbc documentation is not very good, imho, all online example talk just about using the windows gui panel, but this is quite different in linux odbc on a headless server... and other weird things.

                             

                            Anyway, even from my home vpn over 3g connection (so quite a crap connection), I managed to get some debug data I hope.

                             

                            1) I installed a local apache server with a very basic php+odbc script like that above.

                            2) the odbc test script running in apache calls teiid over the vpn asking "select * from ag" and dumping the response array

                            3) performance is even much worse then on LAN, over this vpn/3g crap connection, but I hope logs collected will show some useful info for the LAN slow behaviour.

                             

                            I got two log files, for that single request

                            - mylog_www-data27374.log, which is nearly 9MB

                            - psqlodbc_www-data27374.log which is about 110KB...

                             

                            Attached are the php script and the two (zipped) logs

                             

                            When I go back to office I'll add also other test running the same script from LAN both from linux and windows.

                             

                            btw on my home linux pc

                            - odbc driver (apt-get installed) is odbc-postgresql version 1:09.00.0310-2

                            - unixodbc (apt-get installed) is version 2.2.14p2-5ubuntu3

                             

                            Another test I could try is install a regular postgresql server on the teiid server and try odbc to connect to it if this can be useful.

                             

                            Marco

                            • 11. Re: help needed troubleshooting slow odbc usage
                              shawkins

                              Thanks for the logs.  It would appear php is calling the ColAttSet pg odbc method, which has a path that will perform the same column metadata query for each column in the query - which obviously gets pretty expensive for us.  This is obviously pretty unnecessary.  I'll see if there is anything we can do to prevent this and we may need to file an issue with the pg odbc driver.

                              • 12. Re: help needed troubleshooting slow odbc usage
                                m.ardito

                                I tried what could perhaps be the most useful test: using the same php script to connect to a real postgresql server on the same teiid host.

                                 

                                I created a simple db, one table, with just two fields: "id" (pk), and "test" (text), and inserted two sample records.

                                (to convert my real mysql table to this postgresql server I need to use and ETL, I'll do this, but it needs time...)

                                 

                                then I edited my odbc.ini and php script to load an odbc/dsn pointing to the real postgresql server

                                 

                                the php script loads the web page very fast.

                                 

                                so, it's the same php script, running on the same web server app, connecting to the same host, with the same odbc version, odbc driver, nearly identical dsn definition.

                                 

                                attached you'll find a zip containing

                                - odbc.ini (it's just the same as before, with a new dsn name)

                                - the php script (it's just the same as before, but using the new dsn name)

                                - the (much smaller) odbc debug/trace files I got from the server for a single "select * from tablename where id=1"

                                 

                                hth, and thanks for caring...

                                Marco

                                • 13. Re: help needed troubleshooting slow odbc usage
                                  shawkins

                                  Thanks for the additional log.  I think this should be enough to determine what needs to be done.

                                  • 14. Re: help needed troubleshooting slow odbc usage
                                    shawkins

                                    From what I can see the issue is that we are misreporting atttypmod for many column types.  This appears to hit a unexpected path in the driver which then causes the re-fetching of the column metadata.

                                     

                                    Your query has the columns:

                                     

                                    PGAPI_Columns: table='ag',field_name='id',type=20,name='long'

                                    PGAPI_Columns: table='ag',field_name='rag_soc',type=1043,name='string'

                                    PGAPI_Columns: table='ag',field_name='fg',type=1043,name='string'

                                    PGAPI_Columns: table='ag',field_name='pers_giuridica',type=16,name='boolean'

                                    ...

                                    PGAPI_Columns: table='ag',field_name='note_amm',type=14939,name='lo'

                                    PGAPI_Columns: table='ag',field_name='note_form',type=14939,name='lo'

                                    PGAPI_Columns: table='ag',field_name='note_gen',type=14939,name='lo'

                                    PGAPI_Columns: table='ag',field_name='prossimo_consorziato',type=16,name='boolean'

                                    PGAPI_Columns: table='ag',field_name='caricamento_parziale',type=16,name='boolean'

                                    PGAPI_Columns: table='ag',field_name='data_inserimento',type=1114,name='timestamp'

                                    PGAPI_Columns: table='ag',field_name='id_utente_inserimento',type=20,name='long'

                                    PGAPI_Columns: table='ag',field_name='competitor',type=16,name='boolean'

                                     

                                    And you can see logs similar to:

                                     

                                    [3077781888]PARSE: searchColInfo by attnum=2

                                    [3077781888]PARSE: searchColInfo by attnum=3

                                     

                                    For each of the string columns.  These all have atttypmod values based upon the metadata length of the column.  The other 25 columns are misreported and I think each trigger the column metadata query.  One thing that is confusing to me is:

                                     

                                    PGAPI_Columns: table='ag',field_name='note_amm',type=14939,name='lo'

                                    PGAPI_Columns: table='ag',field_name='note_form',type=14939,name='lo'

                                    PGAPI_Columns: table='ag',field_name='note_gen',type=14939,name='lo'

                                     

                                    We shouldn't be mapping to the large object type.  What version of Teiid are you running on, and what is the source / mapped types for those columns?

                                    1 2 3 Previous Next