db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "George Xu (JIRA)" <j...@apache.org>
Subject [jira] Updated: (DERBY-5066) full table scan when index is used, taking extremely long time in JDBC
Date Thu, 24 Feb 2011 23:02:38 GMT

     [ https://issues.apache.org/jira/browse/DERBY-5066?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

George Xu updated DERBY-5066:
-----------------------------


1) Indeed, the number of rows is much less in the execution plan because I used a smaller
case to generate the plan.
2) It is true that I did not do fetch.   As the result is pretty sometimes (up to 500k or
1000k for example), the app never expects an user to fetch all rows.  We page first 2000 rows
actually.  I assume that the "executeQuery" would only compile the plan and return the pointer
to the first row.  However, this does not look like the case in Derby.  I run in IJ, in both
cases, there is such a long delay before the rows sart to move.
3) The code is a complete snipplet that we are return the first row, and then it is up to
the user to page the resultset.
4) The reason the I had "PID > 0" is represent a case when a user entered a zero in UI,
than made the sql look like that.  It is expected the "PID >0" can cause full table scan
because all PID is bigger than zero, however, the full table scan shall not happen when the
fetch start...not do the actual full table scan.


I tried the following code and it did not help

	CallableStatement cs2 = con.prepareCall("CALL SYSCS_UTIL.SYSCS_COMPRESS_TABLE(?,?,?)");
	cs2.setString(1, "APP");
	cs2.setString(2, "LOGDATA871218");
	cs2.setShort(3, (short) 1);
	cs.execute();

The new plan looks like this

Statement Text: 
	SELECT TIMESTAMP, HOSTPORT AS "HOST ID", PID, SESSIONID, REQUESTID, SUBREQUESTID, STEPID,
TID, COMPONENT, BUILDNUM, LOGLEVELORIG AS "LEVEL", LOGGER, OPERATION, OBJECTTYPE, OBJECTPATH,
STATUS, MESSAGE, DATA, NDX FROM LOGDATA786780 WHERE PID > 0 ORDER BY PID
Parse Time: 93
Bind Time: 16
Optimize Time: 62
Generate Time: 16
Compile Time: 187
Execute Time: 4750
Begin Compilation Timestamp : 2011-02-24 17:58:27.071
End Compilation Timestamp : 2011-02-24 17:58:27.258
Begin Execution Timestamp : 2011-02-24 17:58:27.258
End Execution Timestamp : 2011-02-24 17:58:32.117
Statement Execution Plan Text: 
Sort ResultSet:
Number of opens = 1
Rows input = 69612
Rows returned = 0
Eliminate duplicates = false
In sorted order = false
Sort information: 
	Number of merge runs=38
	Number of rows input=69612
	Number of rows output=69612
	Size of merge runs=[1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791,
1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791,
1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791, 1791]
	Sort type=external
	constructor time (milliseconds) = 0
	open time (milliseconds) = 4750
	next time (milliseconds) = 0
	close time (milliseconds) = 0
	optimizer estimated row count:        22153.56
	optimizer estimated cost:       230567.20

Source result set:
	Project-Restrict ResultSet (2):
	Number of opens = 1
	Rows seen = 69612
	Rows filtered = 0
	restriction = false
	projection = true
		constructor time (milliseconds) = 0
		open time (milliseconds) = 0
		next time (milliseconds) = 672
		close time (milliseconds) = 16
		restriction time (milliseconds) = 0
		projection time (milliseconds) = 16
		optimizer estimated row count:        22153.56
		optimizer estimated cost:       230567.20

	Source result set:
		Table Scan ResultSet for LOGDATA786780 at read committed isolation level using instantaneous
share row locking chosen by the optimizer
		Number of opens = 1
		Rows seen = 69612
		Rows filtered = 0
		Fetch Size = 16
			constructor time (milliseconds) = 0
			open time (milliseconds) = 0
			next time (milliseconds) = 656
			close time (milliseconds) = 16
			next time in milliseconds/row = 0

		scan information:
			Bit set of columns fetched={0, 8, 9, 10, 11, 13, 14, 16, 17, 18, 19, 21, 22, 23, 24, 25,
26, 27, 28}
			Number of columns fetched=19
			Number of pages visited=1608
			Number of rows qualified=69612
			Number of rows visited=69612
			Scan type=heap
			start position:
				null
			stop position:
				null
			qualifiers:
				Column[0][0] Id: 9
				Operator: <=
				Ordered nulls: false
				Unknown return value: true
				Negate comparison result: true
			optimizer estimated row count:        22153.56
			optimizer estimated cost:       230567.20

 

> full table scan when index is used, taking extremely long time in JDBC
> ----------------------------------------------------------------------
>
>                 Key: DERBY-5066
>                 URL: https://issues.apache.org/jira/browse/DERBY-5066
>             Project: Derby
>          Issue Type: Bug
>          Components: Eclipse Plug-in, JDBC
>    Affects Versions: 10.7.1.1
>         Environment: Windows XP environment
>            Reporter: George Xu
>
> When a very large table (500k rows) is used with a column is indexed.   select * from
tab where pid > 0 order by pid takes extremely longer time than select * from tab order
by pid.  Actually, it is 100 times slower.  However, in IJ, ther performance seems to be similar.
 PID column is indexed.
> Here is the code snipplet
> import java.sql.Connection;
> import java.sql.DriverManager;
> import java.sql.ResultSet;
> import java.sql.SQLException;
> import java.sql.Statement;
> public class TestPerformance {
> 	//20343 mill-sec
> 	static String s1 = "SELECT TIMESTAMP, HOSTPORT AS \"HOST ID\", PID, SESSIONID, REQUESTID,
" +
> 	"SUBREQUESTID, STEPID, TID, COMPONENT, BUILDNUM, " +
> 	"LOGLEVELORIG AS \"LEVEL\", LOGGER, OPERATION, OBJECTTYPE, OBJECTPATH, " +
> 	"STATUS, MESSAGE, DATA, NDX FROM LOGDATA871218 where PID > 0 ORDER BY PID";	
> 	//297 million sec.
> 	static String s2 = "SELECT TIMESTAMP, HOSTPORT AS \"HOST ID\", PID, SESSIONID, REQUESTID,
" +
> 	"SUBREQUESTID, STEPID, TID, COMPONENT, BUILDNUM, " +
> 	"LOGLEVELORIG AS \"LEVEL\", LOGGER, OPERATION, OBJECTTYPE, OBJECTPATH, " +
> 	"STATUS, MESSAGE, DATA, NDX FROM LOGDATA871218 ORDER BY PID";	
> 	public static void main(String[] args) throws InstantiationException, IllegalAccessException,
ClassNotFoundException {
> 		Statement stmt3;
> 		try {
> 			//connect'jdbc:derby:C:/devroot/runtime-New_configuration/LogXData';
> 			String db = "C:/devroot/runtime-New_configuration/LogXData";
> 			String driver = "org.apache.derby.jdbc.EmbeddedDriver";
> 			Class.forName(driver).newInstance();
> 			Connection con = DriverManager.getConnection("jdbc:derby:"+db);			
> 			stmt3 = con.createStatement(ResultSet.FETCH_FORWARD, 
> 			        ResultSet.TYPE_FORWARD_ONLY);
> 			long startTime3 = System.currentTimeMillis();
> 			ResultSet rs3 = stmt3.executeQuery(s1); 
> 			long elapsed3 = System.currentTimeMillis() - startTime3;
> 			System.out.println("Statment.executeQuery Dup: " + elapsed3); 
> 		} catch (SQLException e) {
> 			// TODO Auto-generated catch block
> 			e.printStackTrace();
> 		}			
> 	}
> }

-- 
This message is automatically generated by JIRA.
-
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message