Uploaded image for project: 'Apache Trafodion'
  1. Apache Trafodion
  2. TRAFODION-3106

create/drop table painfully slow with blob columns

    Details

    • Type: Improvement
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.4
    • Fix Version/s: None
    • Component/s: sql-exe
    • Labels:
      None
    • Environment:
      CentOS 6.9

      Description

      create/drop table is slow, usually takes seconds to finish, this problem is specially severe for tables with blob columns, which will slow down linearly with the number of blob columns (cqd traf_blob_as_varchar 'off'), which would make it unusable in case tables need to be created and dropped frequently.

      For each blob column, two associated tables will be create, so the time for creating tables with blob columns will increase linearly. In a local testing environment, creating a table with 5 blob columns takes 75 seconds, drop the table without any data takes more than 90 seconds.

      For create table, about half of the time are consumed by calls to createHbaseTable(), and another 30% are consumed by calls to getSeabaseUserTableDesc(), for drop table, most of the time are spend on the calls to getSeabaseUserTableDesc() and ENDTRANSACTION_ERR().

       

      For simple table creation, most of the time is spent on createHbaseTable() function call, while for table dropping, most of the time is spent on ENDTRANSACTION_ERR(), which I assume is where the HBASE tables are actually dropped. Please also note that for the first create/drop operation, time will also be spent on starting compiler processes.

       

      Here is the log for simple create (create table t1 (a int)):

       

      2018-06-25 05:52:29,076, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,SqlCmd::do_execute entry

      2018-06-25 05:52:29,151, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::createSeabaseTable entry

      2018-06-25 05:52:29,151, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::createSeabaseTable2 entry

      2018-06-25 05:52:29,354, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::updateSeabaseMDTable entry

      2018-06-25 05:52:29,765, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::updateSeabaseMDTable exit

      2018-06-25 05:52:29,765, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,createHbaseTable entry

      2018-06-25 05:52:32,051, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,createHbaseTable exit

      2018-06-25 05:52:32,105, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::createSeabaseTable2 exit

      2018-06-25 05:52:32,105, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::updateObjectRedefTime entry

      2018-06-25 05:52:32,153, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::updateObjectRedefTime entry

      2018-06-25 05:52:32,153, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::createSeabaseTable exit

      2018-06-25 05:52:32,179, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,before ENDTRANSACTION_ERR

      2018-06-25 05:52:32,192, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,after ENDTRANSACTION_ERR

      2018-06-25 05:52:32,194, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,SqlCmd::do_execute exit

       

      As we can see total time consume is about 3.1 seconds, and about 2.3 is spent on createHbaseTable.

       

      Here is the log for dropping the simple table:

       

      2018-06-25 05:52:40,007, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,SqlCmd::do_execute entry

      2018-06-25 05:52:40,062, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropSeabaseTable entry

      2018-06-25 05:52:40,062, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropSeabaseTable2 entry

      2018-06-25 05:52:40,226, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,getSeabaseUserTableDesc entry

      2018-06-25 05:52:41,359, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,getSeabaseUserTableDesc exit

      2018-06-25 05:52:42,057, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropSeabaseObject entry

      2018-06-25 05:52:42,569, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropHbaseTable entry

      2018-06-25 05:52:42,588, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropHbaseTable exit

      2018-06-25 05:52:42,588, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropSeabaseObject exit

      2018-06-25 05:52:42,600, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropSeabaseTable2 exit

      2018-06-25 05:52:42,600, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,CmpSeabaseDDL::dropSeabaseTable exit

      2018-06-25 05:52:42,629, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,before ENDTRANSACTION_ERR

      2018-06-25 05:52:46,091, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,after ENDTRANSACTION_ERR

      2018-06-25 05:52:46,163, INFO, SQL.EXE, Node Number: 0, CPU: 0, PIN: 24516, Process Name: $Z000K0G,,,SqlCmd::do_execute exit

       

      For dropping table, most of the time is consumed by ENDTRANSACTION_ERR (3.5 seconds out of 6.1 seconds), which I assume is where the HBase tables are actually dropped. CmpSeabaseDDL::getSeabaseUserTableDesc also takes 1.1 seconds.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              hezhenxing He Zhenxing
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: