Problem with TrendSum

[Metchie]

Hi,
According to my DBA there is a lot of update activity going on the Oracle database (some combination of inserts, deletes, and updates) that is causing archives at the rate of 90 - 100m per minute. This rate seems to be sustained for as long as we want to let it go. The database is currently using only about 9500m of data. At 90m per minute archiving, we are essentially arching the equivalent of the entire database every 1 hour and 45 minutes or so. This appears to be very excessive. A portion of the trend log is below.

2007-01-09 11:43:40:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"Process (id=5040) terminated. 220 sec."
2007-01-09 11:44:39:001,America/Chicago Standard,-06:00,trend_sum,com.hp.ov.pi.transform.parser.TrendSum,ERROR,4388,1276,TSUM_CREATE_EXEC_FAILURE,Failed to create and execute the sum procedure for transformation definition "SH_SR_proc_xSR_OVPA_process_SH_SR_Process". [trace: com.hp.ov.pi.transform.parser.TrendSum.createSumProcedure() TrendSum.java:346]
2007-01-09 11:44:39:016,America/Chicago Standard,-06:00,trend_sum,com.hp.ov.pi.transform.parser.executor.ExecutionManager,ERROR,4388,1276,TSUM_PROC_EXECUTION_FAILURE,Failed to execute procedure "XSR_OVPA_PROTOSH_SR_PROCE684_P". [trace: com.hp.ov.pi.transform.parser.executor.ExecutionManager.checkSQLErrorCode() ExecutionManager.java:270]
2007-01-09 11:44:39:016,America/Chicago Standard,-06:00,trend_sum,,ERROR,4388,1276,DEFAULT_SQL_MSG,java.sql.SQLException: ORA-01555: snapshot too old: rollback segment number 2 with name "_SYSSMU2$" too small
ORA-06512: at "DSI_DPIPE.XSR_OVPA_PROTOSH_SR_PROCE684_P", line 502
ORA-06512: at line 1
. [trace: oracle.jdbc.dbaccess.DBError.throwSqlException() DBError.java:134]
2007-01-09 11:44:39:000,Central Standard Time,-6:00,trend_proc_launch,,DEF_ERROR,1276,6096,0,"The following command exited with code 1: F:/OVPI/bin/trend_sum -f F:/OVPI/scripts/SH_SR_proc.sum"
2007-01-09 11:44:39:000,Central Standard Time,-6:00,trend_proc,,DEF_ERROR,6096,464,0,"Child terminated with exit code 1"
2007-01-09 11:44:39:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"Process (id=6096) terminated. 274 sec."
2007-01-09 11:44:40:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,4632,5044,0,"ODBCmessage. State=22018, NativeError=0, MsgNo=1, Msg=[[DataDirect][ODBC Oracle Wire Protocol driver]Invalid character value. Error in parameter 16.]"
2007-01-09 11:44:40:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,4632,5044,0,"ODBCmessage. State=01000, NativeError=0, MsgNo=1, Msg=[[DataDirect][ODBC Oracle Wire Protocol driver]The currently active transaction was committed before changing the AutoCommit connection option.]"
2007-01-09 11:44:40:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,4632,5044,0,"failed loading data, table XSR_OVPA_FILESYSTEM17911251360, file F:\OVPI\collect\SR\60\BCP/XSR_OVPA_FILESYSTEM_MON-ENT-02.1168362616, rows 400001 <-> 401000. Loaded 743"
2007-01-09 11:44:40:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,4632,5044,0,"failed in ExecuteBcpGatewayCommands processing. resul = -3"
2007-01-09 11:45:00:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"[Pid=5980] F:\OVPI/bin/trend_proc -f F:\OVPI/scripts/thresholdSR.pro"
2007-01-09 11:45:20:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,836,5044,0,"ODBCmessage. State=22018, NativeError=0, MsgNo=1, Msg=[[DataDirect][ODBC Oracle Wire Protocol driver]Invalid character value. Error in parameter 11.]"
2007-01-09 11:45:20:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,836,5044,0,"ODBCmessage. State=01000, NativeError=0, MsgNo=1, Msg=[[DataDirect][ODBC Oracle Wire Protocol driver]The currently active transaction was committed before changing the AutoCommit connection option.]"
2007-01-09 11:45:20:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,836,5044,0,"failed loading data, table XSR_OVPA_CPU17911251360, file F:\OVPI\collect\SR\60\BCP/XSR_OVPA_CPU_MON-ENT-02.1168362616, rows 506001 <-> 507000. Loaded 362"
2007-01-09 11:45:20:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,836,5044,0,"failed in ExecuteBcpGatewayCommands processing. resul = -3"
2007-01-09 11:47:15:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"Process (id=5980) terminated. 135 sec."
2007-01-09 11:55:19:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,3912,5044,0,"ODBCmessage. State=HY000, NativeError=1653, MsgNo=1, Msg=[[DataDirect][ODBC Oracle Wire Protocol driver][Oracle]ORA-01653: unable to extend table DSI_DPIPE.XSR_OVPA_DISK_UPLD1 by 1024 in tablespace DPIPE_UPLOAD_SEG]"
2007-01-09 11:55:19:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,3912,5044,0,"failed executing sql command. FailureCode=-3 [insert into XSR_OVPA_DISK_UPLD1
select DSI_KEY_ID_ , TA_PERIOD , DELTA_TIME , TA_SAMPLES , RECEIVED_TS , RECEIVED_USEC , TA_SYSUPTIME , BYDSK_DEVNAME , BYDSK_DIRNAME , BYDSK_AVG_SERVICE_TIME , BYDSK_PHYS_IO_RATE , BYDSK_UTIL , BYDSK_FS_READ_RATE , BYDSK_FS_WRITE_RATE , BYDSK_RAW_READ_RATE , BYDSK_RAW_WRITE_RATE , BYDSK_VM_IO_RATE , BYDSK_SYSTEM_IO_RATE
from XSR_OVPA_DISK17911251360
where XSR_OVPA_DISK17911251360.DSI_KEY_ID_!= 0 ] "
2007-01-09 11:55:19:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,3912,5044,0,"Error: failed SQLaltInsertloop for table XSR_OVPA_DISK"
2007-01-09 11:55:19:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,3912,5044,0,"failed in ExecuteBcpGatewayCommands processing. resul = -3"
2007-01-09 12:00:00:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"[Pid=2524] F:\OVPI/bin/disk_space"
2007-01-09 12:00:00:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"Process (id=2524) terminated. 0 sec."
2007-01-09 12:00:01:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"[Pid=5844] F:\OVPI/bin/trend_proc -f F:\OVPI/scripts/thresholdSR.pro"
2007-01-09 12:02:49:000,Central Standard Time,-6:00,trendtimer,,INFO,464,720,0,"Process (id=5844) terminated. 168 sec."
2007-01-09 12:03:26:481,America/Chicago Standard,-06:00,trend_sum,com.hp.ov.pi.transform.parser.TrendSum,ERROR,5764,5348,TSUM_CREATE_EXEC_FAILURE,Failed to create and execute the sum procedure for transformation definition "SH_SR_CPU_RSR_OVPA_CPU_SH_SR_CPU". [trace: com.hp.ov.pi.transform.parser.TrendSum.createSumProcedure() TrendSum.java:346]
2007-01-09 12:03:26:497,America/Chicago Standard,-06:00,trend_sum,com.hp.ov.pi.transform.parser.executor.ExecutionManager,ERROR,5764,5348,TSUM_PROC_EXECUTION_FAILURE,Failed to execute procedure "RSR_OVPA_CPUTOSH_SR_CPU508_P". [trace: com.hp.ov.pi.transform.parser.executor.ExecutionManager.checkSQLErrorCode() ExecutionManager.java:270]
2007-01-09 12:03:26:497,America/Chicago Standard,-06:00,trend_sum,,ERROR,5764,5348,DEFAULT_SQL_MSG,java.sql.SQLException: ORA-01555: snapshot too old: rollback segment number 10 with name "_SYSSMU10$" too small
ORA-06512: at "DSI_DPIPE.RSR_OVPA_CPUTOSH_SR_CPU508_P", line 505
ORA-06512: at line 1
. [trace: oracle.jdbc.dbaccess.DBError.throwSqlException() DBError.java:134]
2007-01-09 12:03:26:000,Central Standard Time,-6:00,trend_proc_launch,,DEF_ERROR,5348,1736,0,"The following command exited with code 1: F:/OVPI/bin/trend_sum -f F:/OVPI/scripts/SH_SR_CPU.sum"
2007-01-09 12:03:55:000,Central Standard Time,-6:00,trend_proc,,DEF_ERROR,1736,464,0,"Child terminated with exit code 1"


Any help will be greatly appreciated.

Thanks in advance,
Metchie

[Steven E. Protter]

Shalom,

I can't understand how you came to the conclusion the activity is ecessive. I see errors, and that indicates that either the application is poorly writtten or Java needs to be patched or both.

To come to the conlusion of excesive activity, you'd need to measure that in some way. Transaction level may have risen, the system may be under I/O stress.

I'd agree if you're talking about response time, thats kind of poor.

The first step is to decide there is a problem. You seem to have done that.

The next step is to find the problem.

http://www.hpux.ws/system.perf.sh may be able to help decide where the problem is. Its a good thing to know.

One needs to ask questions:
1) Is the system response time suddenly unacceptable?
2) What has been done to the system or application that may have caused the problem. Software update, some new code, index may need a rebuild?
3)Is the system complying with Oracle's pre-install guidelines. There are a few patches that must be installed prior to Oracle installation and if not, some older versions of Oracle will happily install and then not run right. Check with oracle and if something is missing, get it installed and then relink Oracle.

SEP

[Andrew C Fieldsend]

It looks as though the OVPI System Resources report pack is having problems performing rollups; it seems to be continually trying to execute trend_sum and failing due to Oracle SQL errors.

Are your versions of OVPI, Oracle, and SysRes RP fully compatible with each other? Is this a new OVPI installation, or has there been a change (patch?) which may have caused this?

Andy

[Metchie]

Hi,
The OVPI version 5.1 SP4 was installed on July 27, 2006 and the Oracle data base resides on AIX. There have been no changes to the application or the system. The DBA is in the process of rebuilding the index.
Would changing the following entries to run every three hours provide any relief?

1:00+5 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/Thresholds_Sum.pro
1:00+25 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_OVPA_Hourly.pro
1:00+40 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_Hourly_Reporting.pro
1:00+40 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_Hourly_CPU.pro
1:00+40 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_Hourly_Disk.pro
1:00+40 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_Hourly_LogicalVolume.pro
1:00+40 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_Hourly_NetInterface.pro
1:00+40 - - {DPIPE_HOME}/bin/trend_proc -f {DPIPE_HOME}/scripts/SR_Hourly_Process.pro

The attached file is my trendtimer.sched.

Thanks,
Metchie

[Andrew C Fieldsend]

Changing your trendtimer schedule to run the hourly rollup processing every three hours may reduce your database load, but would definitely mean that your hourly reports wouldn't be up to date for some hours, and may have some effect on their accuracy.

I assume your Oracle version is between 9.2.0.5 and 9.2.0.7, as 9.2.0.8 isn't officially supported until SP6?

You seem to have two different types of error in the log file: basic SQL problems such as invalid character values and insertion failures, and OVPI problems with creating and running trend_sum procedures. It might be worth asking your DBA to check the Oracle logs for more details of these issues from the Oracle side.

Andy

[Metchie]

Andy,

The Oracle version is 9.2.0.6.0. The DBA re-imported the data from the regular overnight export of the data base. I commented out the tend_sum entries in trendtimer.sched and started the OVPI Timer. The following error messages were produced:

2007-01-11 12:55:01:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,4420,4328,0,"ODBCmessage. State=HY000, NativeError=1653, MsgNo=1, Msg=[[DataDirect][ODBC Oracle Wire Protocol driver][Oracle]ORA-01653: unable to extend table DSI_DPIPE.XSR_OVPA_CPU_UPLD1 by 128 in tablespace DPIPE_UPLOAD_SEG]"
2007-01-11 12:55:01:000,Central Standard Time,-6:00,bcp_gateway,,DEF_ERROR,4420,4328,0,"failed executing sql command. FailureCode=-3 [insert into XSR_OVPA_CPU_UPLD1
select DSI_KEY_ID_ , TA_PERIOD , DELTA_TIME , TA_SAMPLES , RECEIVED_TS , RECEIVED_USEC , TA_SYSUPTIME , BYCPU_ID , BYCPU_CPU_SYS_MODE_UTIL , BYCPU_CPU_USER_MODE_UTIL , BYCPU_CPU_TOTAL_UTIL , BYCPU_STATE , BYCPU_INTERRUPT_RATE , BYCPU_CSWITCH_RATE
from XSR_OVPA_CPU17911251360

I am collecting data on 285 nodes using the System Performance report packs. Looking at the attached file it appears that DPIPE_UPLOAD_SEG needs to be increased. This file grew over 500M in less than 1 hour. Any suggestions/recommendations on how this file should be sized.

Thanks,
Metchie

[Andrew C Fieldsend]

There are tablespace sizing guidelines in section 3 of the OVPI 5.1 install guide, which say that the DPIPE_UPLOAD_SEG should be 7% of the total database size. Looking at your tablespace list, 7% of your total database would be about 1.4GB - less than your existing 1.8GB.

I am a little worried about why you only have 168MB free in the upload segment. I'd expect this to be fairly empty. Take a look at the number of rows in the raw data tables; there should be very few, as the raw data is removed by the raw-to-rate processing shortly after being uploaded.