talek / vorax4

A simple yet powerful IDE for Oracle databases, built on top of the widely known Vim editor and Oracle SqlPLUS.
http://talek.github.io/vorax4
MIT License
53 stars 11 forks source link

Performance issue ? #65

Closed AlainVimmer closed 8 years ago

AlainVimmer commented 9 years ago

Hello, I just discovered Vorax and it seems to be a nice match for somebody liking both VIM and Oracle! Everything so far works fine; however when i press "enter" on a table to see its DDL, it takes as much as 1min40 to show it (tried it with several tables). I captured the PL/SQL launched by VIM through SQLPlus, ran it directly on SQLPlus and it takes less than 5 seconds.

Am I missing something ? Could it be my Ruby installation - with which I am not familiar at all ?

Thank you for your answer and keep up the good work!

Alain

talek commented 9 years ago

Hi Alain,

In order to get the definition of a table, Vorax uses DBMS_METADATA.GET_DDL. It actually runs ../vorax/sql/extract_def.sql. If that's what you ran from your sqlplus and it worked in less then 5s, then I believe the wait time is spent somewhere else. You may enable the debugging by setting g:vorax_debug in your .vimrc and look into the generated log file to see where the time is lost. Please let me know if you find anything interesting.

Alec.

AlainVimmer commented 9 years ago

Talek,

Indeed the log file does not seem to show anything peculiar (see below 2nd trace). However there is a lot of time after the last log from the logfile, and the display of the DDL in vim: a good minute ( my time was 14:01:15 when it showed up, so one minute after the last log in the file)

When I ran the SQL from sqlplus it ran in less than 5 seconds(below). One interesting thing is that there is an execution error reported- outlined below, but it does not appear in VIM. Could it be that filtering this part of the output slows things down ? Thank you Alain ------------------------------------------ VORAX LOG FILE------------------------------------------ 2015-09-19 14:00:17.239 [rby] - default_convertor=nil

2015-09-19 14:00:17.239 [rby] - exec: command=[ @C:\Users\ADMINI~1\vimfiles\vorax\sql\extract_def.sql 'WSP_ALAIN' 'DEMO_CUSTOMERS' 'TABLE' ] params={:prep=>"store set C:\Users\ADMINI~1\AppData\Local\Temp\VIB5CCB.tmp.opts replace\nset echo off", :post=>"@C:\Users\ADMINI~1\AppData\Local\Temp\VIB5CCB.tmp.opts", :pack_file=>"C:\Users\ADMINI~1\AppData\Local\Temp\VIC5CCC.tmp.sql"}

2015-09-19 14:00:17.239 [rby] - sent to sqlplus: set markup html off

2015-09-19 14:00:17.239 [rby] - pack_file C:\Users\ADMINI~1\AppData\Local\Temp\VIC5CCC.tmp.sql: store set C:\Users\ADMINI~1\AppData\Local\Temp\VIB5CCB.tmp.opts replace set echo off

pro 

@C:\Users\ADMINI~1\vimfiles\vorax\sql\extract_def.sql 'WSP_ALAIN' 'DEMO_CUSTOMERS' 'TABLE' 

pro 

set termout on 

pro 

@C:\Users\ADMINI~1\AppData\Local\Temp\VIB5CCB.tmp.opts

2015-09-19 14:00:17.239 [rby] - sent to sqlplus: @C:\Users\ADMINI~1\AppData\Local\Temp\VIC5CCC.tmp.sql

------------------------------------------- the DDL showed up at 14:01:15 ----------------------

------------------------------------------DIRECT SQL PLUS OUTPUT (5 sec) -----------------

SQL> @C:\Users\ADMINI~1\vimfiles\vorax\sql\extract_def.sql 'WSP_ALAIN' 'DEMO_CU STOMERS' 'TABLE' ORA-31608: specified object of type OBJECT_GRANT not found: ORA-06512: at "SYS.D BMS_METADATA", line 5746 ORA-06512: at "SYS.DBMS_METADATA", line 8425 ORA-06512: at line 31 4828

CREATE TABLE "WSP_ALAIN"."DEMO_CUSTOMERS" ( "CUSTOMER_ID" NUMBER NOT NULL ENABLE, "CUST_FIRST_NAME" VARCHAR2(20) NOT NULL ENABLE, "CUST_LAST_NAME" VARCHAR2(20) NOT NULL ENABLE, "CUST_STREET_ADDRESS1" VARCHAR2(60), "CUST_STREET_ADDRESS2" VARCHAR2(60), "CUST_CITY" VARCHAR2(30), "CUST_STATE" VARCHAR2(2), "CUST_POSTAL_CODE" VARCHAR2(10), "CUST_EMAIL" VARCHAR2(30), "PHONE_NUMBER1" VARCHAR2(25), "PHONE_NUMBER2" VARCHAR2(25), "URL" VARCHAR2(100), "CREDIT_LIMIT" NUMBER(9,2), "TAGS" VARCHAR2(4000), CONSTRAINT "DEMO_CUST_CREDIT_LIMIT_MAX" CHECK (credit_limit & lt;= 5000) ENABLE, CONSTRAINT "DEMO_CUSTOMERS_PK" PRIMARY KEY ("CUSTOMER_ID ") USING INDEX ENABLE, CONSTRAINT "DEMO_CUSTOMERS_UK" UNIQUE ("CUST_FIRST_NAME& quot;, "CUST_LAST_NAME") USING INDEX ENABLE ) ; CREATE INDEX "WSP_ALAIN"."DEMO_CUST_NAME_IX" ON "WSP_ ALAIN"."DEMO_CUSTOMERS" ("CUST_LAST_NAME", "CUST_F IRST_NAME") ;
AlainVimmer commented 9 years ago

Well, I temporarily modified extract_def.sql to comment out lines generating this error, checked the error disappeared from SQLPlus, but it did not improve performance(I restarted vim too). So that was not the problem.

talek commented 9 years ago

Hi Alain,

Thanks for looking into this. Unfortunately I can't reproduce it on my configuration. So, I'd like to ask you to add some additional logging into autoload/vorax/explorer.vim, within vorax#explorer#OpenDbObject(bang, ...) function. The wait time seems to be spent right after the call of extract_def.sql, most likely into the parsing of the resultset, but this needs to be confirmed.

Many thanks! Alec.

AlainVimmer commented 9 years ago

Hello Alec, I realized I had Ruby log activated, but not VIM based log, so now I have a more complete story. At this point it is clear there is one minute spent in the call to RunVoraxScript from within OpenDBObject, as seen below, executing extract_def.sql.

Strange to me, because I can assure you that extract_def.sql on the same table runs in less than 5 secs directly in SQLPlus. Also, it seems that I get a high CPU usage from VIM during this minute spent.

PS: I am running on a windows VM with ruby 2.0 and Yongwei's build for GVIM(http://wyw.dcweb.cn/#download) because I could not get the standard version to work well with Ruby. Maybe a config issue ?

Thanks

Alain

2015-09-20 13:22:08.720 [vim] - before RunVoraxScript

2015-09-20 13:22:08.720 [vim] - vorax#sqlplus#RunVoraxScript name=extract_def.sql

2015-09-20 13:22:08.720 [rby] - default_convertor=nil

2015-09-20 13:22:08.720 [rby] - exec: command=[ @C:\Users\ADMINI~1\vimfiles\vorax\sql\extract_def.sql 'WSP_ALAIN' 'DEMO_CUSTOMERS' 'TABLE' ] params={:prep=>"store set C:\Users\ADMINI~1\AppData\Local\Temp\VIA8171.tmp.opts replace\nset echo off", :post=>"@C:\Users\ADMINI~1\AppData\Local\Temp\VIA8171.tmp.opts", :pack_file=>"C:\Users\ADMINI~1\AppData\Local\Temp\VIB8172.tmp.sql"}

2015-09-20 13:22:08.720 [rby] - sent to sqlplus: set markup html off

2015-09-20 13:22:08.720 [rby] - pack_file C:\Users\ADMINI~1\AppData\Local\Temp\VIB8172.tmp.sql: store set C:\Users\ADMINI~1\AppData\Local\Temp\VIA8171.tmp.opts replace set echo off

pro 

@C:\Users\ADMINI~1\vimfiles\vorax\sql\extract_def.sql 'WSP_ALAIN' 'DEMO_CUSTOMERS' 'TABLE' 

pro 

set termout on 

pro 

@C:\Users\ADMINI~1\AppData\Local\Temp\VIA8171.tmp.opts

2015-09-20 13:22:08.720 [rby] - sent to sqlplus: @C:\Users\ADMINI~1\AppData\Local\Temp\VIB8172.tmp.sql

2015-09-20 13:23:16.673 [vim] - vorax#explorer#OpenDbObject output=' ORA-31608: specified object of type OBJECT_GRANT not found: ORA-06512: at "SYS.DBMS_METADATA", line 5746 ORA-06512: at "SYS.DBMS_METADATA", line 8425 ORA-06512: at line 31

  4828
CREATE TABLE "WSP_ALAIN"."DEMO_CUSTOMERS" ( "CUSTOMER_ID" NUMBER NOT NULL ENABLE, "CUST_FIRST_NAME" VARCHAR2(20) NOT NULL ENABLE, ....
talek commented 9 years ago

Hi Alain, Just for confirmation, what is the output of: echo g:vorax_version? Likewise, can you please also post the intermediate log messages, those ones prefixed with read output:?

AlainVimmer commented 9 years ago

Hi Alec,

My g:vorax_version=4.3.31

I think we are closing in. Before I detail the log, one thing interesting about my config: the Oracle database is on the same VM as VIM. It is my development environment on my personal PC, so limited CPU power.

I noticed that while gvim indicates 'busy', the processor is close to 100% from the gvim process, and I can hardly get any SQL to be processed by the database. Also, when I look at the Oracle v$sqlarea view to investigate performances, I get a "PLSQL_EXEC_TIME" of 30 seconds for extract_def.sql, when ran through GVIM. (as opposed to 4 secs when ran directly with SQLPlus)

So I concluded that the GVIM polling process of SQL Plus is so processor intensive that it drags down the execution of the extract_def.sql from the database. It probably does not get noticed when the database runs on a separate server, or maybe on the same server but with a Linux box that is better at multitasking than Windows.

To confirm, I added log instructions in the file sqlplus.rb shown below (could not find log messages with read ouput):

def read_output(bytes=4086) 
  Vorax.debug("begin of read_output")  <-------------------------
  output = ""
  raw_output = nil
  begin
    raw_output = @io_read.read_nonblock(bytes)
  rescue Errno::EAGAIN<br>
  end
  if raw_output
    Vorax.debug("read_output, raw_output is not null")  <-------------------------
    raw_output.gsub!(/\r/, '')
    scanner = StringScanner.new(raw_output)
    while not scanner.eos?
      if @look_for == @start_marker
        if text = scanner.scan_until(/#{@look_for}/)
          if text !~ /pro #{@look_for}/
            # Only if it's not part of a PROMPT sqlplus command.
            # This might happen when the "echo" sqlplus option
            # is ON and the begin marker is included into the
            # sql pack file. Because we are using big chunks to
            # read data it's very unlikely that the echoing of the
            # prompt command to be split in the middle.
            @look_for = @end_marker
          end
        else
          scanner.terminate
        end
      end
      if @look_for == @end_marker
        output = scanner.scan(/[^#{@look_for}]*/)
        if scanner.scan(/#{@look_for}/)
          # end of output reached
          scanner.terminate
          @busy = false
        end
      end
    end
  end
  Vorax.debug("read_output 2") <-------------------------
  chunk = output.force_encoding('UTF-8')
  if @current_funnel && !chunk.empty?
    # nokogiri may be confused about those unclosed <p> tags
    # sqlplus emits, so it's better to get rid of them and use
    # <br> instead. 
    Vorax.debug("read_output 2.1") <-------------------------
    @current_funnel.write(br_only(chunk))
    chunk = @current_funnel.read
  end
  Vorax.debug("read_output 3") <-------------------------
  return chunk
end

------------------------------------- LOG OUTPUT 2015-09-21 14:13:11.001 [rby] - begin of read_output

2015-09-21 14:13:11.001 [rby] - read_output 2

2015-09-21 14:13:11.001 [rby] - read_output 3

2015-09-21 14:13:11.001 [rby] - begin of read_output

2015-09-21 14:13:11.001 [rby] - read_output 2

2015-09-21 14:13:11.001 [rby] - read_output 3

........ repeating for about a minute, then.....

2015-09-21 14:14:00.251 [rby] - begin of read_output

2015-09-21 14:14:00.251 [rby] - read_output, raw_output is not null

2015-09-21 14:14:00.251 [rby] - read_output 2

2015-09-21 14:14:00.251 [rby] - read_output 3

2015-09-21 14:14:00.251 [vim] - vorax#explorer#OpenDbObject output=' ORA-31608: specified object of type OBJECT_GRANT not found: ORA-06512: at "SYS.DBMS_METADATA", line 5746 ORA-06512: at "SYS.DBMS_METADATA", line 8425 ORA-06512: at line 31

  4828

CREATE TABLE "WSP_ALAIN"."DEMO_CUSTOMERS"

......

So it does begin to make sense.

What do you think, maybe a "sleep" call would help in the polling process ?

Thank you

Alain

talek commented 8 years ago

Hi Alain,

Thanks for digging into this. The version should be 4.3.53, which is the last available one. That explains why you didn't get those log messages. I'd try first with a small sleep in the vorax#sqlplus#ExecImmediate function. Let's say a sleep 50m, though I'm not sure if that helps in terms of execution time. However, the CPU usage should decrease.

Alec.

AlainVimmer commented 8 years ago

Hello Alec,

That's it, it worked beautifully, now consistently in less than 5 seconds - compared to more than a minute before! Using a sleep timeout at 50m.

So now I can learn more about Vorax, I have a feeling it will become my SQL editor of choice!

Thank you for your help and keep up the good work!

Alain

talek commented 8 years ago

Hi Alain,

Glad it's fixed now! Happy Vorax-ing and thank you for this bug report.

Alec.