[greg42]

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

[RadHaz75]

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

[greg42]

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!

[greg42]

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

[greg42]

Eventually, disabling the BAS service solves the problem, the BB transport tool can now connect to the database.