Very slow logon for administrative sessions

[ShovelMan]

Greetings.. Having an issue where starting a new DSMADMC session takes upwards of 30 seconds.

I already have the DNSLOOKUP set to NO.
Tested NSLOOKUPs on the box just to be sure and they are instant, no delay.
I see the issue whether logging in remotely or directly from the box hosting TSM, no difference.
Multiple server and TSM restarts have been performed.
It seems to be affecting node sessions as well, but I cannot say for 100% certain.
I am not seeing any CPU, Disk or Network-related spikes or issues.

In a possibly related issue, TSM instance start up is now taking over an hour, where it used to be ~20 minutes. This seems to coincide with the logon issue.

We are running 6.3.4 on Windows 2012.

Has anyone seen slow logons NOT caused by DNS issues?

Not sure what other information is needed, so if you need more, please let me know!

 

[marclant]

To rule out the TCP and/or DNS, for the client that is on the same machine as the server, you could used SHAREDMEM instead of TCP. If this is also slow, then this means it has nothing to do with TCPIP and/or DNS resolution.

Should also address the slow start-up, it could be related. Is it slow starting every time, or just the one time? Had the server crashed before the slow start-up? If so, then DB2 is likely doing a recovery. You could check db2diag.log to see what DB2 is doing for the 1 hour start-up.

 

[ShovelMan]

Thanks for the response!

Switching to SHAREDMEM isn't really an option for this production system, unfortunately.

I don't see a file anywhere called db2diag.log.

It's every time now. There was no crash, the TSM instance was halted, the OS shut down gracefully.

One wrinkle is that HADR is stopped on this database, though it used to be replicated async. That shouldn't cause an issue with startup though, given that it is stopped.

I can start the DB2 instance and let it sit for an hour+ THEN start TSM, and it will still take over an hour for TSM to start.

 

[marclant]

Here to help you find db2diag.log: https://www-304.ibm.com/support/docview.wss?uid=swg21380494

When TSM is slow starting, it's normally waiting for DB2 to be available, so that's why I suggested to look at db2diag.log earlier.

 

[LED888]

I'm sure that you are aware that "performance" is one of the toughest issue to resolve since there are no error messages produce.

Since the os shut down, any error in the application and/or system event log?

I would suspect a db reorg but this would only be temporary.

Not too sure if the following would help or not.
TSM 6.3 - Performance

http://www-01.ibm.com/support/knowledgecenter/SSGSG7_6.3.4/com.ibm.itsm.nav.doc/c_performance.html

Resolving and preventing issues related to database growth and degraded performance in Tivoli Storage Manager servers
http://www-01.ibm.com/support/docview.wss?uid=swg21452146

May want to check to see if there are any issues that we are encountering and address at 6.3.5

Server APARs fixed in Tivoli Storage Manager Server Version 6.3 fix pack levels
http://www-01.ibm.com/support/docview.wss?uid=swg21572773

Good Luck,
Sias

 

[moon-buddy]

Thanks for the response!

Switching to SHAREDMEM isn't really an option for this production system, unfortunately.

I don't see a file anywhere called db2diag.log.

It's every time now. There was no crash, the TSM instance was halted, the OS shut down gracefully.

One wrinkle is that HADR is stopped on this database, though it used to be replicated async. That shouldn't cause an issue with startup though, given that it is stopped.

I can start the DB2 instance and let it sit for an hour+ THEN start TSM, and it will still take over an hour for TSM to start.

It is strange that you cannot 'find' the db2diag.log file - all TSM 6.x versions should have this.

How much memory do you have? What is the utilization look like? You may need to add memory or look for a process (aside from TSM) that is loading the system.

A reboot may help

 

[ShovelMan]

It is strange that you cannot 'find' the db2diag.log file - all TSM 6.x versions should have this.

How much memory do you have? What is the utilization look like? You may need to add memory or look for a process (aside from TSM) that is loading the system.

A reboot may help

The system has 256GB of memory. At peak it is using around 66GB

Here's the output from db2diag.log from a startup starting at 11:31

Spoiler

2015-03-02-11.31.17.473000-360 I5489690F320 LEVEL: Event
PID : 856 TID : 2924 PROC : db2set.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 2924
FUNCTION: DB2 UDB, oper system services, db2set_main, probe:40
CHANGE : CFG DB2SET: DB2_KEEPTABLELOCK: From: "OFF" To: "OFF"

2015-03-02-11.31.17.661000-360 I5490012F314 LEVEL: Event
PID : 5096 TID : 5088 PROC : db2set.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 5088
FUNCTION: DB2 UDB, oper system services, db2set_main, probe:40
CHANGE : CFG DB2SET: DB2COMM: From: "TCPIP" To: "TCPIP"

2015-03-02-11.31.30.083000-360 I5490328F327 LEVEL: Event
PID : 5080 TID : 2228 PROC : DB2START.EXE
INSTANCE: TSMPROD NODE : 000
EDUID : 2228
FUNCTION: DB2 UDB, base sys utilities, sqleIssueStartStop, probe:21
DATA #1 : <preformatted>
Single node instance [0] is starting

2015-03-02-11.31.30.083000-360 I5490657F1669 LEVEL: Event
PID : 5080 TID : 2228 PROC : DB2START.EXE
INSTANCE: TSMPROD NODE : 000
EDUID : 2228
FUNCTION: DB2 UDB, base sys utilities, sqleStartStopSingleNode, probe:1130
DATA #1 : String, 27 bytes
E:\TSM\db2\bin\DB2STAR2.EXE
DATA #2 : Hexdump, 256 bytes
0x0000000000137130 : 453A 5C54 534D 5C64 6232 5C62 696E 5C44 E:\TSM\db2\bin\D
0x0000000000137140 : 4232 5354 4152 322E 4558 4500 4E4F 4D53 B2STAR2.EXE.NOMS
0x0000000000137150 : 4700 0000 0000 0000 0000 0000 0000 0000 G...............
0x0000000000137160 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137170 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137180 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137190 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371A0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371B0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371C0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371D0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371E0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371F0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137200 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137210 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137220 : 0000 0000 0000 0000 0000 0000 0000 0000 ................

2015-03-02-11.31.33.763000-360 I5492328F542 LEVEL: Event
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, fast comm manager, sqkfBufferManager::initBufferManager, probe:10
START : Starting FCM Buffer Manager
1 resource group(s).
128 buffers allocated.
Maximum number of buffers supported is 8192.
Total buffer manager memory required for 1 logical and 0 fail-over partition(s) is 925712 bytes.

2015-03-02-11.31.33.779000-360 I5492872F551 LEVEL: Event
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, fast comm manager, sqkfChannelManager::initChannelManager, probe:10
START : Starting FCM Channel Manager
1 resource group(s).
1024 channels allocated.
Maximum number of channels supported is 8192.
Total channel manager memory required for 1 logical and 0 fail-over partitions(s) is 1433624 bytes.

2015-03-02-11.31.33.779000-360 I5493425F548 LEVEL: Event
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, fast comm manager, sqkfSessionManager::initSessionManager, probe:10
START : Starting FCM Session Manager
1 resource group(s).
128 sessions allocated.
Maximum number of sessions supported is 64000.
Total session manager memory required for 1 logical and 0 fail-over partitions is 1683456 bytes.

2015-03-02-11.31.33.779000-360 I5493975F426 LEVEL: Event
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, fast comm manager, sqlkf_init_allocate_shared, probe:500
START : FCM infrastructure started
FCM running in non-shared mode; FCM parallelism degree: 1; comm protocol: TCP/IPv4

2015-03-02-11.31.34.413000-360 I5494403F368 LEVEL: Info
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, base sys utilities, sqleInitSysCtlr, probe:3312
DATA #1 : <preformatted>
Background system application limit set to 500

2015-03-02-11.31.35.666000-360 E5494773F890 LEVEL: Event
PID : 2220 TID : 2204 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 2204
FUNCTION: DB2 UDB, base sys utilities, DB2StartMain, probe:911
MESSAGE : ADM7513W Database manager has started.
START : DB2 DBM
DATA #1 : Build Level, 152 bytes
Instance "TSMPROD" uses "64" bits and DB2 code release "SQL09076"
with level identifier "08070107".
Informational tokens are "DB2 v9.7.600.460", "special_29943", "IP23416_29943", Fix Pack "6".
DATA #2 : System Info, 1568 bytes
System: WIN32_NT TXTSMP01 6.2 AMD64 Family 6, model 62, stepping 4
CPU: total:32 online:32 Cores per socket:1 Threading degree per core:2
Physical Memory(MB): total:262080 free:257605 available:257605
Virtual Memory(MB): total:300992 free:296517
Swap Memory(MB): total:38912 free:38912

2015-03-02-11.31.42.541000-360 I5495665F518 LEVEL: Event
PID : 2220 TID : 4368 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-7 APPID: *LOCAL.TSMPROD.150302173136
AUTHID : TSM
EDUID : 4368 EDUNAME: db2agent (TSMDB1)
FUNCTION: DB2 UDB, config/install, sqlfLogUpdateCfgParam, probe:20
CHANGE : CFG DB TSMDB1 : "Database_memory" From: "42869181" <automatic> To: "48300288" <automatic>

2015-03-02-11.31.43.178000-360 E5496185F426 LEVEL: Info
PID : 2220 TID : 4908 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
EDUID : 4908 EDUNAME: db2loggr (TSMDB1)
FUNCTION: DB2 UDB, data protection services, sqlpgLoggrInitDelOldLog, probe:1440
DATA #1 : <preformatted>
Cleaning up logs from RenameArchNum 1374 to delLimit 1375.

2015-03-02-11.31.57.355000-360 E5496613F476 LEVEL: Event
PID : 2220 TID : 4368 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-7 APPID: *LOCAL.TSMPROD.150302173136
AUTHID : TSM
EDUID : 4368 EDUNAME: db2agent (TSMDB1)
FUNCTION: DB2 UDB, base sys utilities, sqeLocalDatabase::FirstConnect, probe:1000
START : DATABASE: TSMDB1 : ACTIVATED: YES

2015-03-02-11.31.57.954000-360 E5497091F475 LEVEL: Event
PID : 2220 TID : 4736 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-8 APPID: *LOCAL.DB2.150302173157
AUTHID : TSM
EDUID : 4736 EDUNAME: db2stmm (TSMDB1)
FUNCTION: DB2 UDB, Self tuning memory manager, stmmLog, probe:1028
DATA #1 : <preformatted>
Starting STMM log from file number 96

2015-03-02-11.32.38.250000-360 I5497568F368 LEVEL: Event
PID : 4792 TID : 4816 PROC : db2set.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 4816
FUNCTION: DB2 UDB, oper system services, db2set_main, probe:40
CHANGE : CFG DB2SET: DB2_PMODEL_SETTINGS: From: "MAX_BACKGROUND_SYSAPPS:500" To: "MAX_BACKGROUND_SYSAPPS:500"

2015-03-02-11.33.23.384000-360 E5497938F477 LEVEL: Event
PID : 2220 TID : 4640 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-59 APPID: *LOCAL.TSMPROD.150302173309
AUTHID : TSM
EDUID : 4640 EDUNAME: db2agent (idle)
FUNCTION: DB2 UDB, base sys utilities, sqeLocalDatabase::TermDbConnect, probe:2000
STOP : DATABASE: TSMDB1 : DEACTIVATED: YES

2015-03-02-11.33.33.035000-360 I5498417F327 LEVEL: Event
PID : 3164 TID : 3212 PROC : DB2START.EXE
INSTANCE: TSMPROD NODE : 000
EDUID : 3212
FUNCTION: DB2 UDB, base sys utilities, sqleIssueStartStop, probe:21
DATA #1 : <preformatted>
Single node instance [0] is starting

2015-03-02-11.33.33.035000-360 I5498746F1669 LEVEL: Event
PID : 3164 TID : 3212 PROC : DB2START.EXE
INSTANCE: TSMPROD NODE : 000
EDUID : 3212
FUNCTION: DB2 UDB, base sys utilities, sqleStartStopSingleNode, probe:1130
DATA #1 : String, 27 bytes
E:\TSM\db2\bin\DB2STAR2.EXE
DATA #2 : Hexdump, 256 bytes
0x0000000000137130 : 453A 5C54 534D 5C64 6232 5C62 696E 5C44 E:\TSM\db2\bin\D
0x0000000000137140 : 4232 5354 4152 322E 4558 4500 4E4F 4D53 B2STAR2.EXE.NOMS
0x0000000000137150 : 4700 0000 0000 0000 0000 0000 0000 0000 G...............
0x0000000000137160 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137170 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137180 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137190 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371A0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371B0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371C0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371D0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371E0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x00000000001371F0 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137200 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137210 : 0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0000000000137220 : 0000 0000 0000 0000 0000 0000 0000 0000 ................

2015-03-02-11.33.51.713000-360 E5500417F476 LEVEL: Event
PID : 2220 TID : 4640 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-60 APPID: *LOCAL.TSMPROD.150302173333
AUTHID : TSM
EDUID : 4640 EDUNAME: db2agent (TSMDB1)
FUNCTION: DB2 UDB, base sys utilities, sqeLocalDatabase::FirstConnect, probe:1000
START : DATABASE: TSMDB1 : ACTIVATED: YES

2015-03-02-11.37.08.880000-360 I5500895F516 LEVEL: Event
PID : 2220 TID : 4024 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-61 APPID: *LOCAL.DB2.150302173351
AUTHID : TSM
EDUID : 4024 EDUNAME: db2stmm (TSMDB1)
FUNCTION: DB2 UDB, config/install, sqlfLogUpdateCfgParam, probe:20
CHANGE : STMM CFG DB TSMDB1: "Database_memory" From: "48300288" <automatic> To: "43607568" <automatic>

2015-03-02-11.55.10.210000-360 I5501413F441 LEVEL: Warning
PID : 2220 TID : 4948 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 4948 EDUNAME: db2ipccm
FUNCTION: DB2 UDB, fast comm manager, sqkfDynamicResourceMgr::AdjustResources, probe:175
MESSAGE : FCM Automatic/Dynamic Resource Adjustment (Session): 128 successfully
allocated. New total is 256

2015-03-02-11.55.29.647000-360 E5501856F798 LEVEL: Warning
PID : 2220 TID : 2652 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000 DB : TSMDB1
APPHDL : 0-514 APPID: *LOCAL.TSMPROD.150302175652
AUTHID : TSM
EDUID : 2652 EDUNAME: db2agent (TSMDB1)
FUNCTION: DB2 UDB, SQO Memory Management, sqloMemLogPoolConditions, probe:20
DATA #1 : <preformatted>
Reserved heap size exceeded for Database Heap (DBHEAP),
allocating additional unreserved memory.
Requested block size : 8336 bytes.
Physical heap size : 39845888 bytes.
Configured heap size : 39714816 bytes.
Unreserved memory used by heap : 131072 bytes.
Unreserved memory left in set : 13712293888 bytes.

2015-03-02-12.01.34.694000-360 I5502656F443 LEVEL: Warning
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, fast comm manager, sqkfDynamicResourceMgr::AdjustResources, probe:100
DATA #1 : <preformatted>
FCM Automatic/Dynamic Resource Adjustment (Channel): 256 will be released; new total will be 768

2015-03-02-12.31.37.162000-360 I5503101F443 LEVEL: Warning
PID : 2220 TID : 1780 PROC : db2syscs.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 1780 EDUNAME: db2sysc
FUNCTION: DB2 UDB, fast comm manager, sqkfDynamicResourceMgr::AdjustResources, probe:100
DATA #1 : <preformatted>
FCM Automatic/Dynamic Resource Adjustment (Channel): 128 will be released; new total will be 640

2015-03-02-13.32.10.631000-360 E5503546F449 LEVEL: Warning
PID : 3052 TID : 6128 PROC : db2fmp64.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 6128
FUNCTION: DB2 UDB, Health Monitor, HealthIndicator::update, probe:500
MESSAGE : ADM10502W Health indicator "Database Backup Required"
("db.db_backup_req") is in state "Manual backup required" on
"database" "TSMPROD.TSMDB1 ".

2015-03-02-13.42.42.726000-360 E5503997F688 LEVEL: Warning
PID : 3052 TID : 6028 PROC : db2fmp64.exe
INSTANCE: TSMPROD NODE : 000
EDUID : 6028
FUNCTION: DB2 UDB, Health Monitor, HealthIndicator::update, probe:500
MESSAGE : ADM10512W Health indicator "Statistics Collection Required"
("db.tb_runstats_req") is in state "Update statistics required" on
"database" "TSMPROD.TSMDB1 ". Collection (Object Name, Timestamp,
Value, Detail): " ("TSMDB1"."DEVCLASS_SQL", 03/02/2015
13:37:16.000000, 6, RUNSTATS), ("TSMDB1"."STGPOOLS_SQL", 03/02/2015
13:37:08.000000, 6, RUNSTATS)".