Tango database

cscafuri · June 3, 2015, 2:43pm

After the interesting presetation by Gwenaelle at the last Tango meeting and some discussion on the mailing list, we have staterd to test some techniques which may solve, or at least mitigate, the timeout probelms on particular operations on the Tangpo database.
We have the impression that the timeouts may be due to the LOCK TABLE statements used in tha Dabaseds server. Table locks are used because the originale MyISAM MySQL storage enrgine did not support real SQL transactions.

The idea is the to use the InnoDb storage enagine START TRANSACTION / COMMIT statements to guarantee the consistency of the tango database.

The first step is to convert the dtango databse schem to use Innodb.
convertdb.sqlThe attached script performs this chanage.
Stop the Dabaseds server and then run convertdb.sql ( you can paste the script in the myslq shell) with a user with sufficnet privilegs (e.g. root)
Then you can start again the Tango databseds.

dbasemods.tar.gzThe second step is to modify the Database server in oredr to use transaction instead of locks. I modified just tree files from the ltates trunk in the svn reposiory and recompiled the dataabse server. You can find the modified file here:
This is just a test, no much care has been payed to code style and othe possible optimizations.
Test are under way to see if the modified server works correctly in terms of dab management and if the timeout problems are still there. Does any body has a a stress test recipe for the Tango Dabase ?

jkotanski · June 5, 2015, 12:54pm

Hi,

I’ve just made some first tests comparing MyISAM and innoDB and I do not see to many differences in performance.
I’ve used tango 8.1.2 version with an adopted patch from Claudio.
(The concurrency problem appears only when I set to many threads comparing to my cpu cores, e.g.
innodb_thread_concurrency=20 ).

What I see what over-kills db engines is when Database is asked to update only one property in
the property_attribute_device table it removes all properties for this attribute and inserts them back again.

Could someone remind me why all properties for one attribute has to be kept together?
Maybe it is not needed for for innoDB?

Other option could be to have separate tables for each device.

Bests,
Jan

jkotanski · June 9, 2015, 12:46pm

Hello,

I attach a few plots from my stress tests. They show an execution time of read_Position (in simulation mode which writes also 2 others memorized attributes), command_inout(“State”) and state() for OmsVme58 motors versus the local time. One plot is for myisam engine and another for innodb (and versions with the log scale). I attached also the test sources. It seems that performence of the myisam engine with the current settings is better that innodb.
For innodb I used and probably one can tune it better (also the current Database server is more tuned to the myisam engine )

innodb_buffer_pool_size = 1G
innodb_flush_method = O_DIRECT
innodb_log_files_in_group = 2
innodb_file_per_table = 1
innodb_flush_log_at_trx_commit=2
innodb_doublewrite=0
innodb_support_xa=0
innodb_thread_concurrency=1

For both engines I get spikes in the plot with similar maximal high (for innodb are more frequent).
The higher spikes are caused by insert and delete attribute property queries.

Bests,
Jan

jkotanski · June 9, 2015, 12:48pm

attachments

jkotanski · June 9, 2015, 12:49pm

attachments

jkotanski · June 9, 2015, 12:49pm

attachments

jkotanski · June 9, 2015, 12:50pm

sources

jkotanski · June 9, 2015, 12:55pm

I was not able to attached all my files. It seems that it is not possible to do it with files which are larger than 1MB.

agotz · June 9, 2015, 1:03pm

Jan,

thanks for these interesting results. We will comment them in a later post but in the meantime here are the images in jpg format for those of you on cannot read them easily:

agotz · June 9, 2015, 2:23pm

Hi Jan,

indeed InnoDB tables seem to perform much worse than MyISAM. For a simulated device the answer should be immediate as shown on the plot with MyISAM tables. I do not understand the large number of slow calls on InnoDB. Looks like MyISAM is a better choice in our case except for the spikes. We have had another idea here (actually Emmanuel had the idea) to replace the LOCK/DELETE/INSERT/UNLOCK call with UPDATE for memorised attributes. If someone has time to try that please post the patch so everyone can try to stress test it. We will try to do the change ourselves as soon as we have time.

Thanks for this interesting result.

Andy

cscafuri · June 9, 2015, 3:52pm

Hi Jan & Andy,
I perfomed some tests on my development machine. They are defintely not conclusive!
My idea is to read the timing data recorded by the Databseds server. I tested in particular
the performance of DbPutDeviceAttributeProperty2 , which has given us some trobules.
There seems to be a slight advanatge of InnoDB + transactions:


test		average		min		max		
inno+trans	4.207		0.523		140.678		
isam+lock	8.31		0.54		175.253

But I was not able to reproduce the “spikes”, that is the occasional big delays, which we observe on our deployed databases.

I used mysql Ver 14.14 Distrib 5.5.43, for debian-linux-gnu (x86_64) using readline 6.3 on Ubuntu 14.04. MySQL is used “out of the box” with the standard configuration provide by the distribution.

agotz · June 10, 2015, 11:32am

Claudio,

those are in fact good figures and what I implicitly hoped would be true all the time. Do the large delays occur when the tables are bigger or the number of clients increases? Your figures are different for InnoDB compared to Jan’s. Do you have an explanation for this?

Andy

cscafuri · June 10, 2015, 12:24pm

My hypothesis about the difference in performances:

client server, database and mysqld on the same host
host with large memory (24 GB) , i7-3770 CPU @ 3.40GHz , 8 cores

The tests have been done with a more or less constant number of clients and rate of calls.
It is interesting that the minimumtimes are very close for the two configurations and that the average time for InnoDB is about 1/2 of MyISAM.

Claudio

jkotanski · June 15, 2015, 3:20pm

Hi,

Yes indeed, my weak db host can be a kind of catalyser to create the spikes.
My host has 8GB memory and and 4 cores.
Additionally I’m running VM on one of the cores.

For my previous plots, i.e. for innodb and myisam, the min, max and average are comparable.
However, plots say something else (probably those 3 numbers are not enough to describe the spikes).

I’ve replaced DELETE/INSERT by SELECT/UPDATE when only one attribute is updated
but I don’t see too much differences. Spikes have survived.

Therefore, for a short time I’ve run a profiler on my mysql for db_put_device_attribute_property2() queries, i.e.

SET SESSION profiling = 1

add some code to dump the slow queries
and I get top 20 of my slowest queries for the short time run with innodb.


duration slowest_state    query

0.434666 Updating          UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)
0.416155 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.24" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.396943 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.22" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.264904 Updating          UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)
0.264786 Updating          UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)
0.253546 updating          DELETE FROM property_attribute_device_hist WHERE id='29874507' 
0.236474 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.24" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.215407 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.33" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.209728 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.21" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.206369 Updating          UPDATE property_attribute_device SET value='881476' WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionController' AND name LIKE '__value'
0.205035 updating          DELETE FROM property_attribute_device_hist WHERE id='29823493'
0.180331 Updating          UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)
0.179062 updating          DELETE FROM property_attribute_device_hist WHERE id='29808419'
0.174323 Updating          DELETE FROM property_attribute_device_hist WHERE id='29794832'
0.172441 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.32" AND attribute LIKE "StepPositionController" AND name LIKE "__value" 
0.171963 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.31" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.171687 update            INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.23',attribute='StepPositionController',name='__value',count='1',id='29762482',value='1587618'
0.169892 Sending data      SELECT * FROM property_attribute_device WHERE device LIKE "p09/motor/exp.32" AND attribute LIKE "StepPositionController" AND name LIKE "__value"
0.169446 update            INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.23',attribute='StepPositionController',name='__value',count='1',id='29742710',value='1581341'
0.168182 starting          COMMIT

I attach my log file (db.err.gz) if someone wants to look for details (due to many threads some lines in the file are not readable).

To get top 20:


zcat  db.err.gz | grep  'PROFILEQ' | grep -v '2015-06-15' | grep -v 'PROFILING'| sort -k2gr | head -30

To get more profile information


zcat db.err.gz | grep -e 'PROFIL' -e QUERY_ID  | less

Each profile dump consists of a three parts:

sequences of profiling queries denoted by label ‘PROFILING’ with the following column format:

PROFILING <query_id>
one or more query_id of slowest queries (denoted by QUERY_IDs label)
profiles of the slowest queries (listed in QUERY_IDs lines):
[list]
PROFILEQUERY: <query_id> [for the first row of a query]
PROFILEQUERY [for next rows]
[/list]

It seems that Updating/Sending data/update are the slowest tasks in spike queries.

Bests,
Jan

jkotanski · June 17, 2015, 2:18pm

Hi,

I’ve just get an idea to replaced

name LIKE “__value”

to

name=“__value”

I have to run longer tests but it seems that
all my related to those SELECT/UPDATE queries spikes have disappeared.

In SQL ‘_’ denotes any character so if we use it with LIKE
mysql searches for pattern, e.g. for name LIKE “__value”
it search for all names where to first characters are arbitrary.
And it takes time.

I just wonder if it is not dangerous to use property names with ‘_’
in LIKE queries? Theoretically such queries could select more properities than
we want.

Bests,
Jan

agotz · June 17, 2015, 2:33pm

Hi Jan,

this is amazing. I was thinking of replacing LIKE with = but I never thought of the impact the _ could have in the LIKE statement. This could explain a lot of the problems. It would be great if your results are conclusive. In the case we are talking about I do not see the need for the use of LIKE at all. This should be replaced by = in all the places where it is not needed. It would improve the performance for all the columns with primary keys too.

BTW what kind of machine are you running your tests on - physical or virtual? How loaded is the machine when you run the tests? Maybe the LIKE statement is loading the cpu?

Thanks for doing these tests. You might have solved the problem.

Kind regards

Andy

jkotanski · June 18, 2015, 9:25am

Hi,

After longer tests I see that the SELECT/UPDATE spikes are a little bit shorter and less frequent
but they still exist.

For tests I’m using Intel(R) Core™ i5-2500 CPU @ 3.30GHz with 8GB and 4 cores with debian wheezy.
Before I was using VM to simulate multi TANGO_HOST environment but I havn’t seen to much difference
so I’ve switched if off.

My DB tables are with innodb with standard setting plus
innodb_flush_log_at_trx_commit=0 (which turns on buffering during writing to disk , with out it queries are slower)

Quite often spikes are caused by


UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)

Here, tere are my top queries. I add timestamps to see correlation in time between different queries. So it seems that they block each other. Thus, adding core to my machine could reduce the problem.


duration state		 query												                                                                   timestamp
0.218898 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)				                                                                           2015-06-17.16:25:06
0.217402 update		INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.32',attribute='StepPositionController',name='__value',count='1',id='29851404',value='360490'  2015-06-17.16:25:06
0.206082 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.17:16:35
0.204816 update		INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.33',attribute='StepPositionController',name='__value',count='1',id='29899908',value='391363'  2015-06-17.17:16:35
0.168255 Updating	UPDATE property_attribute_device SET value='564460' WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionInternal' AND name='__value'              2015-06-17.22:05:03
0.165729 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)	      			     	       	    			       				   2015-06-17.20:42:52
0.164952 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.20:42:52
0.162638 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.16:04:34
0.157383 Updating	UPDATE property_attribute_device SET value='548123' WHERE device LIKE 'p09/motor/exp.33' AND attribute LIKE 'StepPositionController' AND name='__value'		   2015-06-17.21:37:51
0.15628 Sending data	SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionController' AND name='__value'                        2015-06-17.21:37:51
0.148216 update 	INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.32',attribute='StepPositionController',name='__value',count='1',id='29862956',value='367851'  2015-06-17.16:37:22
0.147066 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.16:37:22
0.128192 Updating	UPDATE property_attribute_device SET value='549175' WHERE device LIKE 'p09/motor/exp.33' AND attribute LIKE 'StepPositionController' AND name='__value'		   2015-06-17.21:39:36
0.127137 Sending data	SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionController' AND name='__value'			   2015-06-17.21:39:36
0.124502 Updating	UPDATE property_attribute_device SET value='356590' WHERE device LIKE 'p09/motor/exp.31' AND attribute LIKE 'StepPositionController' AND name='__value'		   2015-06-17.16:18:36 
0.12336 Sending data	SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.33' AND attribute LIKE 'StepPositionController' AND name='__value'			   2015-06-17.16:18:36
0.123334 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)		     	 	   				     					   2015-06-17.16:08:17 	
0.121975 update		INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.31',attribute='StepPositionInternal',name='__value',count='1',id='29835554',value='350394'	   2015-06-17.16:08:17
0.118151 update		INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.33',attribute='StepPositionController',name='__value',count='1',id='29831900',value='348053'  2015-06-17.16:04:24
0.117685 Updating	UPDATE property_attribute_device SET value='348066' WHERE device LIKE 'p09/motor/exp.31' AND attribute LIKE 'StepPositionController' AND name='__value'		   2015-06-17.16:04:24
0.115573 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)	      			     	       	    			     	 			   2015-06-17.15:37:56
0.114546 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.15:37:56
0.112407 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.19:06:54
0.112257 Updating	UPDATE property_attribute_device SET value='501476' WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionController' AND name='__value'		   2015-06-17.20:20:05
0.110523 Sending data	SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.33' AND attribute LIKE 'StepPositionController' AND name='__value'			   2015-06-17.20:20:05
0.110048 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)		     	 	   				     					   2015-06-17.19:06:54
0.107798 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.19:57:20
0.106377 update		INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.32',attribute='StepPositionController',name='__value',count='1',id='30051372',value='487826'  2015-06-17.19:57:20
0.105856 Updating	UPDATE property_attribute_device SET value='494967' WHERE device LIKE 'p09/motor/exp.31' AND attribute LIKE 'StepPositionInternal' AND name='__value'	   	   2015-06-17.20:09:14
0.105099 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)	      			     	       	    			       				   2015-06-17.18:49:02
0.104216 Updating	UPDATE property_attribute_device SET value='435602' WHERE device LIKE 'p09/motor/exp.31' AND attribute LIKE 'StepPositionInternal' AND name='__value'		   2015-06-17.18:30:18
0.104176 update		INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.33',attribute='StepPositionController',name='__value',count='1',id='29833100',value='348820'  2015-06-17.16:05:41
0.103759 starting	COMMIT 	    				       															   2015-06-17.18:49:02
0.102998 Updating	UPDATE property_attribute_device SET value='494971' WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionInternal' AND name='__value'		   2015-06-17.20:09:14
0.102515 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)	      			     	       	    			       				   2015-06-17.18:33:01
0.102481 Sending data	SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionInternal' AND name='__value'			   2015-06-17.18:30:18
0.102142 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)		     	 	   			       	   					   2015-06-17.19:58:23
0.101914 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													   2015-06-17.19:58:23
0.101765 starting	COMMIT 				       																   2015-06-17.18:33:01
0.101702 Updating	UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)

Also the problem could be caused by common access to harddisk. Between 22:20 and 23:10 TSM disk backup is execuded
and then I get the higher spikes


duration state		 query												                                                                      timestamp

0.934707 Updating	 UPDATE property_attribute_device SET value='600068' WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionController' AND name='__value'              2015-06-17.23:04:25
0.537179 update		 INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.34',attribute='StepPositionController',name='__value',count='1',id='30197592',value='580983'    2015-06-17.22:32:36
0.506604 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:52:47
0.506576 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:32:36
0.506487 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:32:36
0.504438 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:52:47
0.503025 starting	 COMMIT				    																      2015-06-17.22:52:47
0.500263 Updating	 UPDATE property_attribute_device SET value='580971' WHERE device LIKE 'p09/motor/exp.33' AND attribute LIKE 'StepPositionController' AND name='__value'	      2015-06-17.22:32:36
0.498869 Sending data	 SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionController' AND name='__value			      2015-06-17.22:32:36
0.479248 Updating	 UPDATE property_attribute_device SET value='594629' WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionController' AND name='__value'	      2015-06-17.22:55:20
0.476236 Updating	 UPDATE property_attribute_device SET value='599705' WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionController' AND name='__value'	      2015-06-17.23:03:48
0.476168 Updating	 UPDATE property_attribute_device SET value='599704' WHERE device LIKE 'p09/motor/exp.31' AND attribute LIKE 'StepPositionController' AND name='__value'	      2015-06-17.23:03:48
0.476147 Updating	 UPDATE property_attribute_device SET value='592871' WHERE device LIKE 'p09/motor/exp.31' AND attribute LIKE 'StepPositionController' AND name='__value' 	      2015-06-17.22:52:25
0.473693 Sending data	 SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionController' AND name='__value'			      2015-06-17.22:52:25
0.470786 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)		      	  	    	 			      					      2015-06-17.22:32:24
0.467941 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:32:24
0.465877 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.23:05:07   
0.465615 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:32:24
0.465547 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.23:05:07
0.464788 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.23:05:07
0.463986 update		 INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.33',attribute='StepPositionController',name='__value',count='1',id='30227776',value='600479'    2015-06-17.23:05:07
0.462922 update		 INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.31',attribute='StepPositionController',name='__value',count='1',id='30197417',value='580858'    2015-06-17.22:32:24
0.442537 update		 INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.31',attribute='StepPositionController',name='__value',count='1',id='30203916',value='585032'    2015-06-17.22:39:21
0.425195 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:44:14
0.424213 updating	 DELETE FROM property_attribute_device_hist WHERE id='30208330'													      2015-06-17.22:44:14
0.391754 Sending data	 SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionController' AND name='__value'			      2015-06-17.22:55:20
0.384994 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)		      	  	    	 			      					      2015-06-17.23:07:03
0.384858 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.23:07:03
0.382451 updating	 DELETE FROM property_attribute_device_hist WHERE id='30229513'													      2015-06-17.23:07:03
0.361879 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:44:14
0.361471 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:31:10
0.36119 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:31:10
0.361087 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:31:10
0.3607 Updating		 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:31:10
0.354783 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:41:13
0.354044 Updating	 UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)													      2015-06-17.22:41:13
0.33398 Sending data	 SELECT * FROM property_attribute_device WHERE device LIKE 'p09/motor/exp.32' AND attribute LIKE 'StepPositionController' AND name='__value'			      2015-06-17.23:03:48
0.325828 update		 INSERT INTO property_attribute_device_hist SET device='p09/motor/exp.34',attribute='StepPositionController',name='__value',count='1',id='30199928',value='582482'    2015-06-17.22:35:06
0.306212 Updating	 UPDATE property_attribute_device SET value='581213' WHERE device LIKE 'p09/motor/exp.34' AND attribute LIKE 'StepPositionController' AND name='__value'	      2015-06-17.22:32:59

So I don’t thing this problem could be easily solved.

Bests,
Jan

jkotanski · June 18, 2015, 11:22am

Setting

innodb_flush_log_at_trx_commit=0 (which should be more saved)

spikes are a liitle bit higher and dominated by


UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)

and COMMIT or START TRANSATION queries.

One can noticed it using mysql-slow-queries which gives:


# Query_time: 0.425686  Lock_time: 0.000049 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.352119  Lock_time: 0.000029 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.333708  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.315845  Lock_time: 0.000805 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.314773  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.307095  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.278376  Lock_time: 0.000065 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.277032  Lock_time: 0.000056 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.265243  Lock_time: 0.001856 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.258577  Lock_time: 0.258143 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.258066  Lock_time: 0.000046 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.257216  Lock_time: 0.256878 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.246281  Lock_time: 0.000054 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.243335  Lock_time: 0.243034 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.242360  Lock_time: 0.242089 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.239731  Lock_time: 0.000050 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.227009  Lock_time: 0.226595 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.223895  Lock_time: 0.000068 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.223613  Lock_time: 0.223214 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.223209  Lock_time: 0.000032 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.222806  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.221485  Lock_time: 0.221076 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.221196  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.220277  Lock_time: 0.219851 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.219508  Lock_time: 0.219069 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.218968  Lock_time: 0.000077 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.218224  Lock_time: 0.000032 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.208090  Lock_time: 0.207670 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.206722  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.205977  Lock_time: 0.000029 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.203639  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
# Query_time: 0.198432  Lock_time: 0.198199 Rows_sent: 0  Rows_examined: 61
# Query_time: 0.188124  Lock_time: 0.187692 Rows_sent: 0  Rows_examined: 61

Rows_examined: 61 – corresponds to UPDATE device_attribute_history_id …
Rows_examined: 0 – corresponds to COMMIT or START TRANSACTION queries

One can see that “UPDATE device_attribute_history_id …” locks for longer
61 rows (all I’ve got) of device_attribute_history_id table.

jkotanski · June 18, 2015, 2:33pm

Hi,

I don’t know how to speed up

UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)

so for tests I changed

unsigned int device_attribute_property_hist_id = get_id(“device_attribute”,al.get_con_nb());

to

unsigned int device_attribute_property_hist_id = 1;

which messes up my history but it removes my spikes which have left.

I have to wait again for my test but it seems that now my biggest spikes are of order 0.1 - 0.2
and corresponds to INSERT/DELETE into/from property_attribute_device_hist queries

So to sum up I changed:

from myisam to innodb,
from DELETE/INSERT to SELECT/UPDATE,
LIKE to ‘=’ for ‘_’ names
remove UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)

I don’t know how to fix the last issue, any idea?

And also it is not easy to replace LIKE by ‘=’ because patterns are used in some application.

Bests,
Jan

jkotanski · June 19, 2015, 9:06am

Hi,

I’ve just realized that I don’t know why but all my _history_id tables had size 61 (intsead of 1).
That caused spikes of

UPDATE device_attribute_history_id SET id=LAST_INSERT_ID(id+1)

So after dropping rows on _history_id tables those spikes have disappeared.

But why _history_id grows?

Bests,
Jan