BESX transport fails due to DB timeout
Hi,
Having big performance issues with my current BESX server (running on a Win2008 VM), I've installed a new instance on a physical server which rocks. Though, when trying to migrate accounts to the new one with BB transport, I get an SQL timeout error. That doesn't surprise me given the actual poor performances : most of the time, login in to the BAS times out. Before asking my customers to re-activate their device, is there a way to increase the timeout settings ? Thanks Christian |
what kind of vm and version/ how is it configured?
i am running a bunch of bes each with 1500 users just fine, they have 4 gb of ram and 2 3 ghz cpus on esx 3.5 |
The host is a Dell R200, 4x2.8GHz running ESXi 4. The guest system, Windows 2008 server 64-bit, is allocated 2 vCPUs and 2Gb of RAM. VMWare tools are installed.
When I log on to the guest system, it is very slow, and the task manager shows sqlservr.exe *32 and BAS-AS.exe *32 using most of the CPU. SQL Server Express 2005 was installed by the BESX installer. Though, none of the customers (only 16) experiences any performance issue with there device. Here are the transport logs : (08/03 22:26:06.055):{0x0880:8} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.UserValid ationHandler (08/03 22:26:06.055):{0x0880:8} [DEBUG] Queued stop job (08/03 22:26:06.056):{0x0880:8} [DEBUG] Stopped worker thread (08/03 22:26:06.056):{0x0880:8} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.FlowHandl er (08/03 22:26:06.057):{0x0880:8} [DEBUG] Queued stop job (08/03 22:26:06.057):{0x1864:5} [DEBUG] FlowHandler: Received Pulse! (08/03 22:26:06.058):{0x0880:8} [DEBUG] Stopped worker thread (08/03 22:26:06.058):{0x0880:8} [INFO] Enterprise Transporter Shutdown! (08/03 22:26:10.121):{0x16AC:1} [INFO] Migration Starting (08/03 22:26:10.121):{0x16AC:1} [INFO] Manifest: C:\Users\besadmin\Desktop\besx8-to-besx4.xml (08/03 22:26:10.121):{0x16AC:1} [INFO] Preparing to process 1 users (08/03 22:26:10.124):{0x16AC:1} [INFO] Synchronizing policy keys with destination domain (08/03 22:26:10.489):{0x16AC:1} [INFO] Destination domain contains 3 records (08/03 22:26:10.489):{0x16AC:1} [INFO] Source domain contains 2 records (08/03 22:26:10.489):{0x16AC:1} [DEBUG] Synchronizing source policy key set "Site" (08/03 22:26:10.491):{0x16AC:1} [INFO] Policy key pair found in GlobalSettings table with Id = 2 (08/03 22:26:10.491):{0x16AC:1} [INFO] The policy key pair is already present in the destination domain and will not be added (08/03 22:26:10.491):{0x16AC:1} [DEBUG] Synchronizing source policy key set "Trans_1_720F4DB8E8501DBF4FBF82F215A377D4" (08/03 22:26:10.491):{0x16AC:1} [INFO] Policy key pair found in GlobalSettings table with Id = 3 (08/03 22:26:10.491):{0x16AC:1} [INFO] The policy key pair is already present in the destination domain and will not be added (08/03 22:26:10.491):{0x16AC:1} [INFO] Policy key sync complteted successfully (08/03 22:26:10.491):{0x16AC:1} [DEBUG] Registering handler for Validation (08/03 22:26:10.492):{0x16AC:1} [DEBUG] Registering handler for Disable (08/03 22:26:10.494):{0x16AC:1} [DEBUG] UserDisableHandler using "disableUserWaitTime" value of 60 (08/03 22:26:10.494):{0x16AC:1} [DEBUG] Registering handler for Migration (08/03 22:26:10.494):{0x16AC:1} [DEBUG] Registering handler for BasAssignments (08/03 22:26:10.566):{0x16AC:1} [DEBUG] Registering handler for Rollback (08/03 22:26:10.568):{0x16AC:1} [DEBUG] Registering handler for Deletion (08/03 22:26:10.568):{0x16AC:1} [DEBUG] Registering handler for WaitForDisableUser (08/03 22:26:10.568):{0x16AC:1} [DEBUG] Registering handler for WaitForStartupUser (08/03 22:26:10.569):{0x16AC:1} [DEBUG] WaitHandler using waitForStartupUserTimeout value of 60 seconds (08/03 22:26:10.569):{0x16AC:1} [DEBUG] WaitHandler using waitForDisableUserTimeout value of 60 seconds (08/03 22:26:10.576):{0x16AC:1} [INFO] Setting up the notification email (08/03 22:26:10.587):{0x16AC:1} [DEBUG] Registering handler for SwitchService (08/03 22:26:10.587):{0x16AC:1} [DEBUG] Registering handler for SetITPolicy (08/03 22:26:10.589):{0x16AC:1} [DEBUG] ITAdminHandler using switchServiceDetectTimeout value of 90 seconds (08/03 22:26:10.589):{0x16AC:1} [DEBUG] ITAdminHandler using switchServiceStatusTimeout value of 120 seconds (08/03 22:26:10.589):{0x16AC:1} [DEBUG] ITAdminHandler using policyDetectTimeout value of 300 seconds (08/03 22:26:10.589):{0x16AC:1} [DEBUG] ITAdminHandler using policyStatusTimeout value of 120 seconds (08/03 22:26:10.590):{0x16AC:1} [INFO] Hopper getting users from manifest (08/03 22:26:10.590):{0x16AC:1} [INFO] Hopper getting users from manifest (08/03 22:26:10.590):{0x08E4:18} [DEBUG] FlowHandler: Entering Monitor.Wait() (08/03 22:26:10.590):{0x16AC:1} [DEBUG] {user@domain} Starting JOB at 03/08/2010 22:26:10 (08/03 22:26:10.590):{0x16AC:1} [DEBUG] {user@domain} Starting TASK: Start at 03/08/2010 22:26:10 (08/03 22:26:10.590):{0x08E4:18} [DEBUG] FlowHandler: Received Pulse! (08/03 22:26:10.590):{0x08E4:18} [DEBUG] {user@domain} FlowHandler Processing job (08/03 22:26:10.591):{0x08E4:18} [DEBUG] {user@domain} Ending TASK: Start at 03/08/2010 22:26:10 (08/03 22:26:10.591):{0x08E4:18} [DEBUG] FlowHandler: Entering Monitor.Wait() (08/03 22:26:10.591):{0x1B58:9} [INFO] Starting global validation tasks (08/03 22:26:10.591):{0x1B58:9} [INFO] Global validation tasks completed (08/03 22:26:10.591):{0x1B58:9} [INFO] {user@domain} Validating user, TransId=2 (08/03 22:26:10.591):{0x1B58:9} [DEBUG] {user@domain} Checking for user in SourceDatabase: BESMgmt on SRV-BESX01\BLACKBERRY (08/03 22:26:10.591):{0x1B58:9} [DEBUG] {user@domain} User exists in SourceDatabase: BESMgmt on SRV-BESX01\BLACKBERRY (08/03 22:26:10.591):{0x1B58:9} [DEBUG] {user@domain} Checking for user in DestinationDatabase: BESMgmt on SRV-BESX02\BLACKBERRY (08/03 22:26:10.591):{0x1B58:9} [DEBUG] {user@domain} User does not exist in DestinationDatabase: BESMgmt on SRV-BESX02\BLACKBERRY (08/03 22:26:10.591):{0x1B58:9} [INFO] {user@domain} Loading source data for user (08/03 22:26:11.577):{0x1B58:9} [INFO] {user@domain} User device version: 4.6.0.303 (08/03 22:26:11.577):{0x1B58:9} [INFO] {user@domain} Loading destination data for user (08/03 22:26:11.577):{0x1B58:9} [INFO] {user@domain} Checking UserConfigId availability (08/03 22:26:11.577):{0x1B58:9} [INFO] {user@domain} UserConfigId can be preserved with DeviceUserId column (08/03 22:26:11.640):{0x1B58:9} [INFO] {user@domain} Validating user data (08/03 22:26:11.640):{0x1B58:9} [INFO] {user@domain} *** User appears valid for migration *** (08/03 22:26:11.640):{0x1B58:9} [INFO] {user@domain} User validated successfully, TransId=2 (08/03 22:26:11.640):{0x08E4:18} [DEBUG] FlowHandler: Received Pulse! (08/03 22:26:11.640):{0x08E4:18} [DEBUG] {user@domain} FlowHandler Processing job (08/03 22:26:11.640):{0x08E4:18} [DEBUG] {user@domain} Ending TASK: Validation at 03/08/2010 22:26:11 (08/03 22:26:11.640):{0x08E4:18} [DEBUG] FlowHandler: Entering Monitor.Wait() (08/03 22:26:11.642):{0x1A28:10} [INFO] {user@domain} Disabling user in source domain, TransId=2 (08/03 22:26:11.646):{0x1A28:10} [DEBUG] {user@domain} Disabling user in source database (08/03 22:26:13.461):{0x1A28:10} [INFO] {user@domain} User successfully disabled (08/03 22:26:43.493):{0x1A28:10} [ERROR] {user@domain} Exception disabling user: System.Data.SqlClient.SqlException: Expiration du délai d'attente. Le délai d'attente s'est écoulé avant la fin de l'opération ou le serveur ne répond pas. -> in English : timeout or server not responding à System.Data.SqlClient.SqlConnection.OnError(SqlExc eption exception, Boolean breakConnection) à System.Data.SqlClient.SqlInternalConnection.OnErro r(SqlException exception, Boolean breakConnection) à System.Data.SqlClient.TdsParser.ThrowExceptionAndW arning(TdsParserStateObject stateObj) à System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) à System.Data.SqlClient.SqlCommand.FinishExecuteRead er(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString) à System.Data.SqlClient.SqlCommand.RunExecuteReaderT ds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async) à System.Data.SqlClient.SqlCommand.RunExecuteReader( CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result) à System.Data.SqlClient.SqlCommand.InternalExecuteNo nQuery(DbAsyncResult result, String methodName, Boolean sendToPipe) à System.Data.SqlClient.SqlCommand.ExecuteNonQuery() à Rim.Enterprise.Brk.EnterpriseTransporter.SourceDat abase.DisableUser(BlackBerryUser user) (08/03 22:26:43.495):{0x1A28:10} [WARNING] The SQL error (-2) was been logged 1 times for the database BESMgmt on SRV-BESX01\BLACKBERRY (08/03 22:26:43.495):{0x1A28:10} [ERROR] {user@domain} Disable user failed, TransId=2 (08/03 22:26:43.495):{0x08E4:18} [DEBUG] FlowHandler: Received Pulse! (08/03 22:26:43.495):{0x08E4:18} [DEBUG] {user@domain} FlowHandler Processing job (08/03 22:26:43.495):{0x08E4:18} [DEBUG] {user@domain} Ending TASK: Disable at 03/08/2010 22:26:43 (08/03 22:26:43.496):{0x08E4:18} [DEBUG] FlowHandler: Entering Monitor.Wait() (08/03 22:26:43.497):{0x1ABC:14} [INFO] {user@domain} Rolling back the user data, TransId=2 (08/03 22:26:43.500):{0x1ABC:14} [INFO] {user@domain} User successfully rolledback, TransId=2 (08/03 22:26:43.500):{0x08E4:18} [DEBUG] FlowHandler: Received Pulse! (08/03 22:26:43.500):{0x08E4:18} [DEBUG] {user@domain} FlowHandler Processing job (08/03 22:26:43.500):{0x08E4:18} [DEBUG] {user@domain} Ending TASK: Rollback at 03/08/2010 22:26:43 (08/03 22:26:43.500):{0x08E4:18} [INFO] {user@domain} Completing job TransId=2 (08/03 22:26:43.502):{0x08E4:18} [DEBUG] {user@domain} Ending JOB at 03/08/2010 22:26:43 (08/03 22:26:43.504):{0x08E4:18} [DEBUG] Transporter Migrate Status: Processed=1, Moved=0, Failed=1, Warnings=0, Skipped=0 (08/03 22:26:43.504):{0x08E4:18} [INFO] Hopper getting next load balanced user from manifest (08/03 22:26:43.504):{0x08E4:18} [DEBUG] FlowHandler: Entering Monitor.Wait() (08/03 22:26:43.504):{0x04AC:19} [DEBUG] Shut down called (08/03 22:26:43.504):{0x04AC:19} [INFO] Enterprise Transporter Shutting Down... (08/03 22:26:43.504):{0x04AC:19} [INFO] **** START USER SUMMARY **** (08/03 22:26:43.504):{0x04AC:19} [INFO] {user@domain} MigrationFailed (08/03 22:26:43.504):{0x04AC:19} [INFO] **** END USER SUMMARY **** (08/03 22:26:43.505):{0x04AC:19} [INFO] Migration Complete! (08/03 22:26:46.807):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.UserValid ationHandler (08/03 22:26:46.807):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.807):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.807):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.UserDisab leHandler (08/03 22:26:46.807):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.808):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.808):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.UserMigra tionHandler (08/03 22:26:46.808):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.808):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.808):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.BasHandle r (08/03 22:26:46.808):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.809):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.809):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.RollbackH andler (08/03 22:26:46.809):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.810):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.810):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.UserDelet ionHandler (08/03 22:26:46.810):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.810):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.811):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.WaitHandl er (08/03 22:26:46.811):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.817):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.817):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.ITAdminHa ndler (08/03 22:26:46.817):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.822):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.822):{0x04AC:19} [DEBUG] Trying to stop worker thread: Rim.Enterprise.Brk.EnterpriseTransporter.FlowHandl er (08/03 22:26:46.822):{0x04AC:19} [DEBUG] Queued stop job (08/03 22:26:46.822):{0x08E4:18} [DEBUG] FlowHandler: Received Pulse! (08/03 22:26:46.822):{0x04AC:19} [DEBUG] Stopped worker thread (08/03 22:26:46.823):{0x04AC:19} [INFO] Enterprise Transporter Shutdown! |
If that can help, here is the result of BBCheck :
Detection Report [GENERAL] Current User: EXCHANGE\besadmin Host Name: SRV-BESX01 OS Version: Service Pack 2 [BES] Platform: Exchange Version: 5.0.1 (Bundle 5) Install Path: C:\Program Files (x86)\Research In Motion\BlackBerry Enterprise Server\ MAPI Profile: BlackBerryServer MAPI GC: [SERVICE_ACCOUNT] BlackBerry Server Account: EXCHANGE\besadmin Domain Group Membership: Exchange View-Only Administrators [EXCHANGE_PERMISSIONS] Server: CN=SRV-EXC01,CN=Servers,CN=Exchange Administrative Group (FYDIBOHF23SPDLT),CN=Administrative Groups,CN=Premiere Organisation,CN=Microsoft Exchange,CN=Services,CN=Configuration,DC=exchange, DC=local Accounts/Groups found with Send As/Receive As permissions: Account: exchange\besadmin has Send As Permissions Account: exchange\besadmin has Receive As Permissions Account: exchange\besadmin has Administer Information Store Group: exchange view-only administrators has All [MAPI_SUBSYSTEM] EXMAPI32.DLL: 6.5.8153.0 (C:\Program Files (x86)\ExchangeMapi\exmapi32.dll) MAPI32.DLL: 1.0.2536.0 (C:\Windows\system32\mapi32.dll) EMSMDB32.DLL: 6.5.8153.0 (C:\Program Files (x86)\ExchangeMapi\emsmdb32.dll) CDO.DLL: 6.5.8153.0 (C:\Program Files (x86)\ExchangeMapi\cdo.dll) [GC] Domain Name: exchange.local GC Name: SRV-EXC01.exchange.local GC IP: XX.XX.XX.26 [DATABASE] Hostname: SRV-BESX01\BLACKBERRY DB Name: BESMgmt Location: Remote DB info via TSQL: Express Edition (9.00.4035.00 SP3) SQL Version: Unable to find SQL version! MSDE Version: Unable to find MSDE version! MDAC Version: 6.0.6002.18005 MSADO15.DLL: 6.0.6002.18005 (C:\Program Files (x86)\Common Files\System\ado\msado15.dll) [DB_BES_INSTANCE_VERSIONS] BESX01: 5.0.1.4 [JAVA] Version: 1.6 Path: C:\Program Files (x86)\Java\jre6 MDS JVM Path: C:\Program Files (x86)\Java\jre1.6.0_15\bin\client\jvm.dll [DOT_NET_FRAMEWORK] Version 1.0: MISSING Version 1.1 (1.1.4322): MISSING Version 2.0 (2.0.50727): INSTALLED Version 3.0 (3.0.0456.30): MISSING [MSMQ] MSMQ Version: [NETWORK] Local IP: XX.XX.XX.8 TCP/IP Providor: 6.0.6001.18000 (C:\Windows\System32\wsock32.dll) Winsock2 File: 6.0.6002.18005 (C:\Windows\System32\winrnr.dll) [SRP_CONNECTIVITY] Host: fr.srp.blackberry.com IP: 193.109.81.33 Status: Connection Successful [SYSTEM_INFORMATION] Processor: Processor Identifier: Intel64 Family 6 Model 23 Stepping 10 Processor Vendor: GenuineIntel Processor Name: Intel(R) Xeon(R) CPU X3360 @ 2.83GHz Processor Speed: 2834 MHz Number of CPUs: 2 Memory: Memory In Use: 97% Total Memory: 2,095,844 KB Memory Available: 42,368 KB Memory Limit: 262,920 KB Available Commit: 1,318,448 KB Hard Drive: Time Info: Uptime: 7 days 18 hours 57 minutes 6 seconds Time Zone: Paris, Madrid (heure d' [SYSTEM_HOTFIXES] [PROCESSES] Number of Processes: 72 Process PID Threads System 4 115 smss.exe 476 4 csrss.exe 544 17 wininit.exe 588 3 csrss.exe 600 7 winlogon.exe 644 3 services.exe 676 8 lsass.exe 688 25 lsm.exe 696 10 svchost.exe 848 7 svchost.exe 908 8 LogonUI.exe 980 8 svchost.exe 988 16 svchost.exe 224 5 svchost.exe 360 54 SLsvc.exe 372 4 svchost.exe 520 14 svchost.exe 584 21 svchost.exe 776 27 svchost.exe 1112 17 spoolsv.exe 1316 16 BBAttachServer.exe 1412 115 BlackBerryController.exe 1508 10 BlackberryRouter.exe 1572 10 BESAlert.exe 1628 6 sqlservr.exe 1824 43 Aua.exe 1912 2 CDPService64.exe 1940 2 auaJW.exe 1964 14 Scheduler.exe 892 2 bschJW.exe 1176 18 svchost.exe 832 5 svchost.exe 1252 3 snmp.exe 484 5 sqlbrowser.exe 672 7 sqlwriter.exe 1376 3 VMwareService.exe 2100 5 svchost.exe 2176 4 VMUpgradeHelper.exe 2536 3 BBAttachMonitor.exe 2744 6 BlackBerryExtension.exe 3356 13 dllhost.exe 4796 13 svchost.exe 5060 10 msdtc.exe 496 11 csrss.exe 7060 11 winlogon.exe 3400 3 rdpclip.exe 6452 4 taskeng.exe 4748 9 dwm.exe 4864 4 explorer.exe 6492 20 VMwareTray.exe 3000 1 VMwareUser.exe 7100 3 GoogleToolbarNotifier.exe 1752 5 jusched.exe 3508 1 SystemTray64.exe 2864 5 conime.exe 5052 1 taskmgr.exe 6352 5 BAS-NCC.exe 2504 32 BlackBerrySyncServer.exe 5240 88 BlackBerryMailStoreSrvr.exe 6016 15 BlackBerryPolicyServer.exe 3956 24 BlackBerryAgent.exe 6720 49 taskeng.exe 3876 5 BAS-AS.exe 5680 161 BlackBerryDispatcher.exe 3992 54 BBConvert.exe 2664 2 BBConvert.exe 7012 2 BBConvert.exe 6064 2 wuauclt.exe 1612 2 TrustedInstaller.exe 3820 9 BBConvert.exe 4636 2 BBCheck.exe 6792 6 |
Eventually, disabling the BAS service solves the problem, the BB transport tool can now connect to the database.
|
All times are GMT -5. The time now is 08:21 PM. |
Powered by vBulletin® Version 3.8.11
Copyright ©2000 - 2024, vBulletin Solutions Inc.