search

CenturyLinkCloud / mdw

https://centurylinkcloud.github.io/mdw/
MIT License
46 stars 10 forks source link

Excessive continuous MySQL database network traffic #249

Open donaldoakes opened 6 years ago

donaldoakes commented 6 years ago

We need to optimize our dbcp2 configuration. In addition to testOnBorrow, we also have testWhileIdle set to true. From the docs it's not obvious how often the query runs to validate idle connections. Since we have timeBetweenEvictionRunsMillis not set, and it defaults to -1, it would seem that testWhileIdle should have no effect. But see below where one second of activity from a query log repeats the following steps 22 times for the sake of 8 or 9 actual queries.

     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback

Here's one second (unabridged) from the query log:

171103 17:32:16    26 Query select 1
     26 Query SET autocommit=0
     26 Query update ACTIVITY_INSTANCE set STATUS_CD=4, STATUS_MESSAGE='true', END_DT=now() where ACTIVITY_INSTANCE_ID=1619873
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query insert into WORK_TRANSITION_INSTANCE (WORK_TRANS_INST_ID, WORK_TRANS_ID, PROCESS_INST_ID, STATUS_CD, START_DT, DEST_INST_ID, CREATE_DT, CREATE_USR) values (null, 14, 297972, 1, now(), 8, now(), 'MDWEngine')
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query insert into ACTIVITY_INSTANCE (ACTIVITY_INSTANCE_ID, ACTIVITY_ID, PROCESS_INSTANCE_ID, STATUS_CD, START_DT, CREATE_DT, CREATE_USR) values (null, 8, 297972, 2, now(), now(), 'MDWEngine')
     26 Query update WORK_TRANSITION_INSTANCE set STATUS_CD=6, END_DT=now(), DEST_INST_ID=1619874 where WORK_TRANS_INST_ID=1306772
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query insert into DOCUMENT (DOCUMENT_ID, CREATE_DT, DOCUMENT_TYPE, OWNER_TYPE, OWNER_ID, STATUS_CODE, STATUS_MESSAGE) values (null, now(), 'java.lang.String', 'ADAPTER_REQUEST', 1619874, 0, '')
     26 Query insert into DOCUMENT_CONTENT (DOCUMENT_ID, CONTENT) values (7612037, '{\n  "originatorInfo": {\n    "originatorName": "SDWF",\n    "statusBackURLs": "http://sdwf-itv1.dev.qintra.com/mdw/services/sd/v1/status/sdwf4e999cca9f41",\n    "comment": "Service Delivery Workflow"\n  },\n  "commonInfo": {\n    "publicUserID": "8632664715",\n    "requestStatusCode": "202",\n    "requestActionType": "delete",\n    "offering": "dhp",\n    "correlationID": "sdwf4e999cca9f41",\n    "comment": "Looking up Service plan",\n    "requestStatus": "Accepted",\n    "requestStatusMessage": "Looking up Service plan",\n    "orderingSystem": "ENS"\n  }\n}')
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query insert into DOCUMENT (DOCUMENT_ID, CREATE_DT, DOCUMENT_TYPE, OWNER_TYPE, OWNER_ID, STATUS_CODE, STATUS_MESSAGE) values (null, now(), 'org.json.JSONObject', 'ADAPTER_REQUEST_META', 7612037, 0, '')
     26 Query insert into DOCUMENT_CONTENT (DOCUMENT_ID, CONTENT) values (7612038, '{\n  "HttpMethod": "POST",\n  "RequestURL": "http://yzeus.lab.af.qwest.net/OMNIVue/RESTService/StatusManager/StatusSubmitService",\n  "headers": {\n    "correlation-id": "sdwf4e999cca9f41",\n    "ordering-channel": "ENS",\n    "reply-to": "http://sdwf-itv1.dev.qintra.com/mdw/services/sd/v1/status/sdwf4e999cca9f41"\n  }\n}')
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query insert into DOCUMENT (DOCUMENT_ID, CREATE_DT, DOCUMENT_TYPE, OWNER_TYPE, OWNER_ID, STATUS_CODE, STATUS_MESSAGE) values (null, now(), 'java.lang.String', 'ADAPTER_RESPONSE', 1619874, 200, 'OK')
     26 Query insert into DOCUMENT_CONTENT (DOCUMENT_ID, CONTENT) values (7612039, '{"commonResponseInfo":{"statusCode":"200","correlationID":"sdwf4e999cca9f41","status":"SUCCESS","publicUserID":"8632664715","statusMessage":"SM Details submitted successfully."}}')
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query insert into DOCUMENT (DOCUMENT_ID, CREATE_DT, DOCUMENT_TYPE, OWNER_TYPE, OWNER_ID, STATUS_CODE, STATUS_MESSAGE) values (null, now(), 'org.json.JSONObject', 'ADAPTER_RESPONSE_META', 7612039, 0, '')
     26 Query insert into DOCUMENT_CONTENT (DOCUMENT_ID, CONTENT) values (7612040, '{\n  "HttpMethod": "POST",\n  "RequestURL": "http://yzeus.lab.af.qwest.net/OMNIVue/RESTService/StatusManager/StatusSubmitService",\n  "headers": {\n    "Connection": "Keep-Alive",\n    "Content-Type": "application/json;charset=UTF-8",\n    "Date": "Fri, 03 Nov 2017 17:32:16 GMT",\n    "Expires": "Thu, 01 Jan 1970 00:00:00 GMT",\n    "HTTP": "HTTP/1.1 200 OK",\n    "Keep-Alive": "timeout=15, max=500",\n    "Server": "Jetty(7.5.4.v20111024)",\n    "Set-Cookie": "JSESSIONID=omnivuetest1ctr7o02ucdqxf7zmjp8skwz7a.omnivuetest1c;Path=/OMNIVue",\n    "Transfer-Encoding": "chunked",\n    "Vary": "Accept-Encoding,User-Agent",\n    "WWW-Authenticate": "Basic realm=\\"CT\\"",\n    "X-UA-Compatible": "IE=Edge"\n  }\n}')
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
     26 Query update ACTIVITY_INSTANCE set STATUS_CD=4, STATUS_MESSAGE=null, END_DT=now() where ACTIVITY_INSTANCE_ID=1619874
     26 Query commit
     26 Query rollback
     26 Query SET autocommit=1
     26 Query select 1
     26 Query SET autocommit=0
jbrojdeCTL commented 6 years ago

Does it seem strange that the only queries listed are INSERT/UPDATE statements? I would think there would be lots of SELECTs in there as well (besides the validation query performed by the pool). Also, the default for connections is auto_commit, but we (MDW) set the auto_commit to false AFTER borrowing the connection from the pool, and it does seem that right after each SELECT 1, we set autocommit=0, so I think this might actually be correct (from a pool behavior perspective), meaning that we have executing code that is requesting a DB connection that many times.