This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 255880 - Execution times are always showing 0.001s and never real execution time
Summary: Execution times are always showing 0.001s and never real execution time
Status: RESOLVED FIXED
Alias: None
Product: db
Classification: Unclassified
Component: Show Data (show other bugs)
Version: 8.1
Hardware: PC Mac OS X
: P3 normal (vote)
Assignee: matthias42
URL:
Keywords:
Depends on:
Blocks: 144491
  Show dependency tree
 
Reported: 2015-10-12 16:14 UTC by brettryan
Modified: 2016-02-02 03:26 UTC (History)
0 users

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description brettryan 2015-10-12 16:14:49 UTC
All executions seem to always produce the same output:

Executed successfully in 0.001 s.
Line 1, column 1

Execution finished after 0.001 s, 0 error(s) occurred.


However, it's most often wrong, I just executed a long running task that took ~10 minutes and that was the result from that execution.
Comment 1 matthias42 2015-10-13 19:12:40 UTC
Thank you for checking this - there is an issue, but most probably not what you think - run

select hash('SHA256',  STRINGTOUTF8('Password4'), 10000000);

I get:

Executed successfully in 6,427 s.
Line 1, column 1

Execution finished after 6,427 s, 0 error(s) occurred.

There are two different effects you could see:

1.) The statement is either executed twice (once to get the resultset and then in the form "select count(*) from (select hash('SHA256',  STRINGTOUTF8('Password4'), 10000000) a" to get the row count or the resultset is scrolled to the end (expensive operation).
2.) Reported is only the first execution time, not both execution times (from above) and not fetch time.

Can you reproduce this? If so I would turn this into an enhancement request to be clearer in the report.
Comment 2 brettryan 2015-10-19 01:30:42 UTC
I just timed this and it took 25 seconds, but got the following output:

Executed successfully in 4.353 s.
Line 2, column 1

Execution finished after 4.353 s, 0 error(s) occurred.


The execution time IMHO should reflect the actual statements execution time within the RDBMS. I use these timings to optimise my queries. This helps me tweak my query (introduce left joins to increase performance).

Presently I use a stopwatch to do this.
Comment 3 matthias42 2016-01-29 22:38:49 UTC
With the change committed as:

http://hg.netbeans.org/core-main/rev/e8ce25b6abf8
http://hg.netbeans.org/core-main/rev/d785e9724faa

With that changeset the following informations are reported after an execution:

Per statement:
- execution time (time Statement#execute or PreparedStatement#execute takes)
- count of rows the statement modified (potentially multiple)
- fetch time (time taken to fetch the resultset, that is:
  - scrolling to correct position
  - extract date for page
  - potentially scroll to end of resultset)

For all statements (the whole script):
- time taken for all operations


This way you should be able to get rid of your stopwatch and some more sensible numbers.

Please test the nightly build when available. Please change status of this issue to VERIFIED if you find this fixes your problem.

Please note: While the numbers should give you better insight into the execution, the application might still show different times. For example the netbeans db support fetches metadata and currently issues the statement twice. These two parts take time, that is part of the time for all operations, but not part of execution- and fetchtime.
Comment 4 matthias42 2016-01-29 22:44:14 UTC
To check the support for multiple resultsets + update counts I used mssql:

================================ Preparation ===========================================

- Load AdventureWorksLT2008R2 as base
- create table address_last_change (ts datetime);
- create trigger SalesLT.x on SalesLT.address after insert, update as
 DELETE FROM SalesLT.address_last_change;
 insert into SalesLT.address_last_change VALUES (CURRENT_TIMESTAMP);


================================ Sample SQL ===========================================
-- Insert a pseudo entry into address_last_change (makes delete visible in output)
insert into SalesLT.address_last_change VALUES (CURRENT_TIMESTAMP);
-- Request output of execution plan (will yield 3 resultsets)
set statistics profile on;
-- Insert pseudo data into address
insert into SalesLT.address (AddressLine1, AddressLine2, City, StateProvince, CountryRegion, PostalCode)
VALUES
('Addr1', 'Addr2', 'C', 'SP', 'CR', 'PC');

================================ Sample Result ===========================================
Executed successfully in 0,021 s.
1 row affected.
Line 2, column 1


Executed successfully in 0,001 s.
Line 4, column 1


Executed successfully in 0,022 s.
1 row affected.
Fetching resultset took 0,007 s.
2 rows affected.
Fetching resultset took 0,003 s.
1 row affected.
Fetching resultset took 0,001 s.
Line 6, column 1

Execution finished after 0,315 s, no errors occurred.
Comment 5 Quality Engineering 2016-01-31 02:39:46 UTC
Integrated into 'main-silver', will be available in build *201601310002* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)

Changeset: http://hg.netbeans.org/main-silver/rev/e8ce25b6abf8
User: Matthias Blaesing <matthias42@netbeans.org>
Log: #255880: Report fetchtimes for resultsets and support multiple update counts
Comment 6 brettryan 2016-01-31 18:05:11 UTC
This is looking great, though there is still a lot of time missing:

I'm connecting to a remote database over a VPN connection where executions can be slow. On a test I get the following:


Executed successfully in 0.615 s.
Fetching resultset took 1.752 s.
Line 2, column 1

Execution finished after 24.878 s, no errors occurred.


Even with your explanation I'm not sure where the missing 22 seconds is.
Comment 7 matthias42 2016-02-02 03:26:28 UTC
These number seem excessive. I just did a quick test with the simplest of queries:

select * from <table>

against a sample mysql db over a simulated WAN link with 100ms latency injected via netem.

I ran that query with the netbeans self profiler and indeed the numbers add up:

Total run time reported: 800ms, execution 200 ms, fetching 0ms

The profiler identified:

100 ms checking if connection is alive
100 ms execution itself
100 ms extract warnings if present 
100 ms for an additional query that fetches the total row count
200 ms to fetch default values for table editing
100 ms to fetch foreign key info
100 ms to fetch primary key info

While I rounded each entry a few ms  the numbers pretty much reflect the simulated roundtrip time.

Could you please help me with two things?

1. Which DBMS is used in your case and
2. Could you take a profile when you execute your long running sample query? (Only the phase from the moment just before you execute the statement until result is display is needed)
3. What type of SQL do you issue? (SELECT, INSERT, CREATE?)

You could see the same problem as described in:

https://netbeans.org/bugzilla/show_bug.cgi?id=257458

the create statement issued there in itself looks pretty harmless, but it triggers rebuild of the table structure tree in the services table and the storm of SQLs (see attachments (see attachment SQL-log.txt) is created by the jdbc driver when the metadata model is rebuild.