Too many contention logs (send lock and jbalock)

[Shahanavaz Syed]

Hi All,

I have a cluster with 2 Datanodes + 2 Mgmd Nodes (Sql co-hosted) + 2 Api nodes.
When i run a benchmark for testing primary key reads, using 32/64/128 threads generating 512K transactions with each doing 10 read operations (using only C++ NDB API using multiple connections).

Often i see below mentioned messages in the log, followed Johan Andersons blog to debug and follwoed all the methods still i see below logs.

Importantly i see jbalock logs even in idle cluster. Could anyone put some light on where to fine tune configurations?

######################################################################
Config.ini:
######################################################################
[TCP DEFAULT]
SendBufferMemory=8M
ReceiveBufferMemory=8M

[NDB_MGMD DEFAULT]
#PortNumber=1186
Datadir=/var/lib/mysql-cluster/

[NDB_MGMD]
NodeId=49
#Hostname=192.168.20.1
Hostname=192.168.3.5
#LogDestination=FILE:filename=ndb_1_cluster.log,maxsize=10000000,maxfiles=6
ArbitrationRank=1

[NDB_MGMD]
NodeId=50
#Hostname=192.168.20.3
Hostname=192.168.3.6
#LogDestination=FILE:filename=ndb_2_cluster.log,maxsize=10000000,maxfiles=6
ArbitrationRank=1

[NDBD DEFAULT]
NoOfReplicas=2
#ServerPort=2200
#FileSystemPathUndoFiles=/data/mysqlcluster/
#FileSystemPathDataFiles=/data/mysqlcluster/
#Datadir=/usr/local/mysql/data
#FileSystemPathDD=/usr/local/mysql/data
#BackupDataDir=/usr/local/mysql/data//backup/
Datadir=/home/sshahanavaz/mysql/data
FileSystemPathDD=/home/sshahanavaz/mysql/data
BackupDataDir=/home/sshahanavaz/mysql/data//backup/

DataMemory=15328M
IndexMemory=2600M
LockPagesInMainMemory=1
#LockPagesInMainMemory=0

MaxNoOfConcurrentOperations=500000
MaxNoOfConcurrentTransactions=256k

StringMemory=25
MaxNoOfTables=4096
MaxNoOfOrderedIndexes=2048
MaxNoOfUniqueHashIndexes=512
MaxNoOfAttributes=24576
MaxNoOfTriggers=14336

### Params for REDO LOG
FragmentLogFileSize=256M
InitFragmentLogFiles=SPARSE
NoOfFragmentLogFiles=82
RedoBuffer=48M
NoOfFragmentLogParts=16
#NoOfFragmentLogParts=8

TransactionBufferMemory=8M


TimeBetweenGlobalCheckpoints=1000
TimeBetweenEpochs=100

TimeBetweenEpochsTimeout=0

### Params for LCP
DiskCheckpointSpeedInRestart=100M
DiskCheckpointSpeed=10M
TimeBetweenLocalCheckpoints=20

### Heartbeating
HeartbeatIntervalDbDb=15000
HeartbeatIntervalDbApi=15000

### Params for setting logging
MemReportFrequency=30
BackupReportFrequency=10
LogLevelStartup=15
LogLevelShutdown=15
LogLevelCheckpoint=8
LogLevelNodeRestart=15

### Params for BACKUP
BackupMaxWriteSize=1M
BackupDataBufferSize=24M
BackupLogBufferSize=16M
BackupMemory=40M

### Params for ODIRECT
#Reports indicates that odirect=1 can cause io errors (os err code 5) on some systems. You must test.
#ODirect=1

### Watchdog
TimeBetweenWatchdogCheckInitial=60000
### Watchdog syed added it
#TimeBetweenWatchDogCheck=12000

### TransactionInactiveTimeout - should be enabled in Production
TransactionInactiveTimeout=60000
### New 7.1.10 redo logging parameters
RedoOverCommitCounter=3
RedoOverCommitLimit=20
### REALTIME EXTENSIONS
RealTimeScheduler=1
### REALTIME EXTENSIONS FOR 6.3 ONLY
SchedulerExecutionTimer=80
SchedulerSpinTimer=40

### DISK DATA 384M,1024M
SharedGlobalMemory=384M
DiskPageBufferMemory=1024M

### Multithreading
#MaxNoOfExecutionThreads=16
MaxNoOfExecutionThreads=28
ThreadConfig=ldm={count=12,cpubind=1,2,3,4,5,6,7,8,9,10,11,12},main={cpubind=13},io={cpubind=13},rep={cpubind=14},tc={count=7,cpubind=15,16,17,18,19,20,21},recv={count=4,cpubind=22,23,24,25},send={count=3,cpubind=26,27,28}

### Increasing the LongMessageBuffer b/c of a bug (20090903)
LongMessageBuffer=16M

BatchSizePerLocalScan=512

[NDBD]
NodeId=1
#Hostname=192.168.20.5
Hostname=192.168.3.7

### REALTIME ASPECTS - THREAD BINDING
### READ http://johanandersson.blogspot.com/2008/02/mysql-cluster-features-what-they-are.html#realtime
#LockExecuteThreadToCPU=X
#LockMaintThreadsToCPU=Y

[NDBD]
NodeId=2
#Hostname=192.168.20.7
Hostname=192.168.3.8

### REALTIME ASPECTS - THREAD BINDING
### READ http://johanandersson.blogspot.com/2008/02/mysql-cluster-features-what-they-are.html#realtime
#LockExecuteThreadToCPU=X
#LockMaintThreadsToCPU=Y

[MYSQLD DEFAULT]
DefaultOperationRedoProblemAction=QUEUE
BatchSize=512
#BatchByteSize=2048K
#MaxScanBatchSize=2048K

[MYSQLD]
NodeId=51
#Hostname=192.168.20.1
Hostname=192.168.3.5

[MYSQLD]
NodeId=52
#Hostname=192.168.20.3
Hostname=192.168.3.6

[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
[API]
### SLOTS (one for each ndb_mgmd) FOR HELPER APPLICATIONS SUCH AS ndb_show_tables etc
[API]
[API]
### SLOT FOR CMON
[API]
#Hostname=192.168.20.100
Hostname=192.168.3.100

#######################################################################
NDBMTD Logs:
########################################################################
send lock node 2 waiting for lock, contentions: 1030000 spins: 1059836448
send lock node 70 waiting for lock, contentions: 7800 spins: 5233960
send lock node 67 waiting for lock, contentions: 8200 spins: 5446708
send lock node 69 waiting for lock, contentions: 8000 spins: 5502298
send lock node 68 waiting for lock, contentions: 7400 spins: 4573819
send lock node 67 waiting for lock, contentions: 8400 spins: 5579015
send lock node 70 waiting for lock, contentions: 8000 spins: 5389696
send lock node 69 waiting for lock, contentions: 8200 spins: 5633581
send lock node 2 waiting for lock, contentions: 1035000 spins: 1065483375
send lock node 68 waiting for lock, contentions: 7600 spins: 4707362
send lock node 67 waiting for lock, contentions: 8600 spins: 5720857
send lock node 70 waiting for lock, contentions: 8200 spins: 5551434
send lock node 69 waiting for lock, contentions: 8400 spins: 5754686
send lock node 70 waiting for lock, contentions: 8400 spins: 5685310
send lock node 67 waiting for lock, contentions: 8800 spins: 5848968
send lock node 68 waiting for lock, contentions: 7800 spins: 4823219
send lock node 69 waiting for lock, contentions: 8600 spins: 5896554
send lock node 2 waiting for lock, contentions: 1040000 spins: 1071300881
send lock node 69 waiting for lock, contentions: 8800 spins: 6040945
send lock node 70 waiting for lock, contentions: 8600 spins: 5843134
send lock node 67 waiting for lock, contentions: 9000 spins: 5983361
send lock node 68 waiting for lock, contentions: 8000 spins: 4942993
send lock node 69 waiting for lock, contentions: 9000 spins: 6188716
send lock node 67 waiting for lock, contentions: 9200 spins: 6122170
send lock node 70 waiting for lock, contentions: 8800 spins: 5991747
send lock node 2 waiting for lock, contentions: 1045000 spins: 1076936003
send lock node 68 waiting for lock, contentions: 8200 spins: 5068770
send lock node 69 waiting for lock, contentions: 9200 spins: 6352635
jbalock thr: 0 waiting for lock, contentions: 9000 spins: 994012
jbalock thr: 1 waiting for lock, contentions: 2600 spins: 591969
jbalock thr: 0 waiting for lock, contentions: 9200 spins: 1009903
jbalock thr: 0 waiting for lock, contentions: 9400 spins: 1029773