Requests taking over 2 minutes
benjes Mar 23, 2010 11:32 AMHi
we are currently evaluating teiid (6.2) but I am having major problems with requests taking more than 2 minutes when the same request from Squirel to the DB (a Progress DB) takes less than a second. The odd thing is that the same request can sometimes take only a few seconds with Teiid (when run shortly after a clean start of teiid).
2010-03-23 15:02:27,688 INFO [Worker9_UVOSProgress Connector<1>3] org.teiid.COMMAND_LOG - 2010.03.23 15:02:27.688 START DATA SRC COMMAND: startTime=2010.03.23 15:02:27.688 requestID=5.1 sourceCommandID=2 subTxID=a000041:c3e6:4ba8d4ed:4 modelName=UVOS connectorBindingName=UVOSProgress Connector<1> sessionID=5 principal=admin sql=SELECT DISTINCT * FROM UVOS.PORDER.PUB.DETAILS AS g_0, UVOS.PORDER.PUB.HEADER AS g_1 WHERE g_0.HDR_ID = g_1.HDR_ID2010-03-23 15:05:48,488 INFO [Worker13_QueryProcessorQueue91] org.teiid.COMMAND_LOG - 2010.03.23 15:05:48.489 END USER COMMAND: endTime=2010.03.23 15:05:48.488 requestID=5.1 txID=a000041:c3e6:4ba8d4ed:4 sessionID=5 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=100 isCancelled=false errorOccurred=false
Somehow this sounds more like a timeout problem somewhere.
Another thing I've noticed is that when Hibernate starts up (we are running Seam 2.2/Hibernate3 on JBoss 4.2.3, I know old) a lot of request are generated. These request only finish a few minutes later.
Here is one of those request:
2010-03-23 14:49:56,409 INFO [Worker3_SocketWorker13] org.teiid.COMMAND_LOG - 2010.03.23 14:49:56.409 START USER COMMAND: startTime=2010.03.23 14:49:56.409 requestID=1.1 txID=null sessionID=1 applicationName=JDBC principal=admin vdbName=VIRT_UVOS vdbVersion=1 sql=SELECT NULL AS TABLE_CAT, v.Name AS TABLE_SCHEM, GroupFullName AS TABLE_NAME, e.Name AS COLUMN_NAME, convert(decodeString(DataType, 'string,12,boolean,-7,time,92,date,91,timestamp,93,integer,4,float,7,double,8,bigdecimal,2,biginteger,2,byte,-6,short,5,long,-5,char,1,object,2000,clob,2005,blob,2004,xml,2009', ','), short) AS DATA_TYPE, DataType AS TYPE_NAME, CASE WHEN (DataType IN ('string', 'char', 'clob', 'blob', 'boolean', 'date', 'time', 'timestamp', 'object')) THEN CASE WHEN ElementLength <= 0 THEN convert(decodeString(DataType,'string,4000,boolean,1,time,8,date,10,timestamp,29,integer,10,float,20,double,20,bigdecimal,20,biginteger,19,byte,3,short,5,long,19,char,1,object,2147483647,clob,2147483647,blob,2147483647,xml,2147483647',','), integer) ELSE ElementLength END ELSE CASE WHEN Precision <= 0 THEN convert(decodeString(DataType,'string,4000,boolean,1,time,8,date,10,timestamp,29,integer,10,float,20,double,20,bigdecimal,20,biginteger,19,byte,3,short,5,long,19,char,1,object,2147483647,clob,2147483647,blob,2147483647,xml,2147483647',','), integer) ELSE Precision END END AS COLUMN_SIZE, NULL AS BUFFER_LENGTH, Scale AS DECIMAL_DIGITS, Radix AS NUM_PREC_RADIX, convert(decodeString(NullType, 'No Nulls, 0, Nullable, 1, Unknown, 2', ','), integer) AS NULLABLE, Description AS REMARKS, DefaultValue AS COLUMN_DEF, NULL AS SQL_DATA_TYPE, NULL AS SQL_DATETIME_SUB, CharOctetLength AS CHAR_OCTET_LENGTH, Position AS ORDINAL_POSITION, decodeString(NullType, 'No Nulls, YES, Nullable, NO, Unknown, '' ''', ',') AS IS_NULLABLE, NULL AS SCOPE_CATALOG, NULL AS SCOPE_SCHEMA, NULL AS SCOPE_TABLE, NULL AS SOURCE_DATA_TYPE, CASE WHEN e.IsAutoIncremented = 'true' THEN 'YES' ELSE 'NO' END AS IS_AUTOINCREMENT FROM System.Elements e CROSS JOIN System.VirtualDatabases v WHERE UCASE(v.Name) LIKE ? ESCAPE '\' AND UCASE(GroupFullName) LIKE ? ESCAPE '\' AND UCASE(e.Name) LIKE ? ESCAPE '\' ORDER BY TABLE_NAME, ORDINAL_POSITION
and about 14 minutes later:
2010-03-23 15:12:22,749 INFO [Worker17_QueryProcessorQueue92] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.749 END USER COMMAND: endTime=2010.03.23 15:12:22.749 requestID=1.1 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=20 isCancelled=false errorOccurred=false
2010-03-23 15:12:22,763 INFO [Worker15_QueryProcessorQueue93] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.763 END USER COMMAND: endTime=2010.03.23 15:12:22.763 requestID=1.0 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=1 isCancelled=false errorOccurred=false
2010-03-23 15:12:22,764 INFO [Worker18_QueryProcessorQueue94] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.764 END USER COMMAND: endTime=2010.03.23 15:12:22.764 requestID=1.2 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=1 isCancelled=false errorOccurred=false
2010-03-23 15:12:22,771 INFO [Worker18_QueryProcessorQueue97] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.771 END USER COMMAND: endTime=2010.03.23 15:12:22.771 requestID=1.4 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=1 isCancelled=false errorOccurred=false
2010-03-23 15:12:22,771 INFO [Worker15_QueryProcessorQueue96] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.771 END USER COMMAND: endTime=2010.03.23 15:12:22.771 requestID=1.5 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=35 isCancelled=false errorOccurred=false
2010-03-23 15:12:22,778 INFO [Worker19_QueryProcessorQueue95] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.778 END USER COMMAND: endTime=2010.03.23 15:12:22.778 requestID=1.3 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=41 isCancelled=false errorOccurred=false
2010-03-23 15:12:22,781 INFO [Worker9_SocketWorker178] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.781 END USER COMMAND: endTime=2010.03.23 15:12:22.781 requestID=1.6 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=0 isCancelled=true errorOccurred=false
2010-03-23 15:12:22,781 INFO [Worker9_SocketWorker178] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.781 END USER COMMAND: endTime=2010.03.23 15:12:22.781 requestID=1.7 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=0 isCancelled=true errorOccurred=false
2010-03-23 15:12:22,781 INFO [Worker9_SocketWorker178] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.781 END USER COMMAND: endTime=2010.03.23 15:12:22.781 requestID=1.8 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=0 isCancelled=true errorOccurred=false
2010-03-23 15:12:22,781 INFO [Worker9_SocketWorker178] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.781 END USER COMMAND: endTime=2010.03.23 15:12:22.781 requestID=1.9 txID=null sessionID=1 principal=admin vdbName=VIRT_UVOS vdbVersion=1 finalRowCount=0 isCancelled=true errorOccurred=false
2010-03-23 15:12:22,804 INFO [Worker19_QueryProcessorQueue98] org.teiid.COMMAND_LOG - 2010.03.23 15:12:22.804 END USER COMMAND: endTime=2010.03.23 15:12:22.804 requestID=C.6 txID=null sessionID=null principal=null vdbName=null vdbVersion=null finalRowCount=1 isCancelled=false errorOccurred=false
Any ideas what might be going wrong?
Other problems I often see is 'Socket Closed Exception' (my session timeout is commented out in deploy.properties
or
com.metamatrix.jdbc.MMSQLException: The specified session ID "5" is invalid. It cannot be found in the userbase.
Any ideas what might be going wrong?
Regards
Immo