Jump to content


Photo

MySQL Query Performance Issue - x2crm 6.9

mysql performance innodb myisam tagging slow query

  • Please log in to reply
6 replies to this topic

#1 Alberto

Alberto

    Advanced Member

  • Premium Members
  • PipPipPip
  • 91 posts
  • LocationWashington

Posted 12 August 2017 - 06:31 PM

Hello, I have been dealing with a performance crippling situation with X2CRM related to MySQL queries to the 'x2_trigger_logs' table. This manifests specifically whenever we interact with tags on records, such as adding a single tag to a contact.

 

I wrote a simple PHP script that uses X2CRM's API to test performance of Create, Lookup, Update, Delete and saw the following poor performance:

08-11-2017 22:28:33.190000 Creating contact.
08-11-2017 22:28:34.310000 Done.

08-11-2017 22:28:34.310000 Lookup contact.
08-11-2017 22:28:34.360000 Done.

08-11-2017 22:28:34.360000 Adding tag to contact.
08-11-2017 22:28:43.750000 Done.

08-11-2017 22:28:43.750000 Adding note to contact.
08-11-2017 22:28:45.940000 Done.

08-11-2017 22:28:45.940000 Deleting contact.
08-11-2017 22:28:49.780000 Done.

Total time elapsed: 16.5868570805 seconds.

As seen above, most of the 16 seconds is taken up with the "add tag" operation.

 

I have been working with our server admin to help isolate the issue and have identified the following query to be the cause:

SELECT COUNT(*) FROM x2_trigger_logs t;

We logged slow queries in MySQL and found that this particular query seems to be called 74 times when adding 1 tag to a contact in our case. Each query execution time is measured to be 0.16 seconds:

mysql> SELECT COUNT() FROM x2_trigger_logs t;
+----------+
| COUNT() |
+----------+
| 500000 |
+----------+
1 row in set (0.16 sec)

Below we can see the slow log timings for one "add tag to contact" operation:

# Query_time: 0,108733 Lock_time: 0,000667 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,143326 Lock_time: 0,000117 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,020223 Lock_time: 0,000090 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023354 Lock_time: 0,000123 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,110335 Lock_time: 0,000081 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,046776 Lock_time: 0,000095 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,114055 Lock_time: 0,000076 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,050419 Lock_time: 0,000041 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023053 Lock_time: 0,000090 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,115704 Lock_time: 0,000066 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,024761 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,126456 Lock_time: 0,000071 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,029691 Lock_time: 0,000043 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022982 Lock_time: 0,000085 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,122913 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,042518 Lock_time: 0,000119 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,110395 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,054122 Lock_time: 0,000039 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023069 Lock_time: 0,000107 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,114085 Lock_time: 0,000065 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,043029 Lock_time: 0,000102 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,120918 Lock_time: 0,000077 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,035168 Lock_time: 0,000034 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023252 Lock_time: 0,000083 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,121647 Lock_time: 0,000070 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,043686 Lock_time: 0,000088 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,120966 Lock_time: 0,000073 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,035233 Lock_time: 0,000034 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023241 Lock_time: 0,000088 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,113551 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,051815 Lock_time: 0,000088 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,129238 Lock_time: 0,000075 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,026755 Lock_time: 0,000052 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022935 Lock_time: 0,000094 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,135328 Lock_time: 0,000071 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,030015 Lock_time: 0,000109 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,133382 Lock_time: 0,000074 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,031044 Lock_time: 0,000044 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022996 Lock_time: 0,000092 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,121591 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,043867 Lock_time: 0,000090 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,120075 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,036094 Lock_time: 0,000045 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022999 Lock_time: 0,000096 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,126852 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,038542 Lock_time: 0,000106 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,123067 Lock_time: 0,000101 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,041513 Lock_time: 0,000043 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023012 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,114935 Lock_time: 0,000066 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,050427 Lock_time: 0,000094 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,125180 Lock_time: 0,000103 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,031061 Lock_time: 0,000035 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023015 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,114702 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,050768 Lock_time: 0,000098 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,116401 Lock_time: 0,000069 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,039639 Lock_time: 0,000042 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022856 Lock_time: 0,000101 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,134674 Lock_time: 0,000072 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,030727 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,116739 Lock_time: 0,000069 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,047695 Lock_time: 0,000041 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,047473 Lock_time: 0,000107 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,127621 Lock_time: 0,000075 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,037800 Lock_time: 0,000090 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,115011 Lock_time: 0,000065 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,049486 Lock_time: 0,000042 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022797 Lock_time: 0,000094 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,127977 Lock_time: 0,000075 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,037516 Lock_time: 0,000090 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,110380 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,054164 Lock_time: 0,000035 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023125 Lock_time: 0,000117 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,122504 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,042859 Lock_time: 0,000091 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,128829 Lock_time: 0,000076 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,027380 Lock_time: 0,000070 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023089 Lock_time: 0,000121 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,122215 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,043164 Lock_time: 0,000092 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,127072 Lock_time: 0,000071 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,029135 Lock_time: 0,000034 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,023047 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,113734 Lock_time: 0,000087 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,051643 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,116783 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,047555 Lock_time: 0,000039 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022892 Lock_time: 0,000095 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,137589 Lock_time: 0,000079 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,027725 Lock_time: 0,000091 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,114247 Lock_time: 0,000081 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,050185 Lock_time: 0,000035 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022840 Lock_time: 0,000096 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,141953 Lock_time: 0,000074 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,023370 Lock_time: 0,000094 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,112142 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,044138 Lock_time: 0,000038 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022989 Lock_time: 0,000120 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,133209 Lock_time: 0,000078 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,032129 Lock_time: 0,000094 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,121637 Lock_time: 0,000074 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,042797 Lock_time: 0,000045 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022903 Lock_time: 0,000095 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,124094 Lock_time: 0,000093 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,041362 Lock_time: 0,000092 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,126776 Lock_time: 0,000073 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,037710 Lock_time: 0,000043 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022966 Lock_time: 0,000102 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,117217 Lock_time: 0,000070 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,048257 Lock_time: 0,000089 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,122213 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,033802 Lock_time: 0,000040 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022777 Lock_time: 0,000132 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,138520 Lock_time: 0,000077 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,026862 Lock_time: 0,000091 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,112981 Lock_time: 0,000069 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,051570 Lock_time: 0,000044 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022970 Lock_time: 0,000092 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,114645 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,050807 Lock_time: 0,000122 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,115831 Lock_time: 0,000068 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,040165 Lock_time: 0,000046 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022829 Lock_time: 0,000098 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,129765 Lock_time: 0,000071 Rows_sent: 1 Rows_examined: 500000
# Query_time: 0,035642 Lock_time: 0,000087 Rows_sent: 0 Rows_examined: 0
# Query_time: 0,116264 Lock_time: 0,000067 Rows_sent: 1 Rows_examined: 500001
# Query_time: 0,039860 Lock_time: 0,000044 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,022871 Lock_time: 0,000117 Rows_sent: 0 Rows_examined: 1
# Query_time: 0,127930 Lock_time: 0,000072 Rows_sent: 1 Rows_examine
all query with Rows_examined: 500000 (500001) related to x2_trigger_logs

Above you can see the 'x2_trigger_logs' table is currently full with 500,000 records (sized down from the X2CRM default of 1 million).

 

All of our X2CRM tables are using the MySQL InnoDB storage engine. We did find significant improvement would be gained if the 'x2_trigger_logs' table were converted to MyISAM.

 

See this resource as to why this query is particularly slow with InnoDB:

https://www.percona....-innodb-tables/

 

We have only tested the MyISAM table conversion in a test environment and are not sure if this is safe to do in production.

 

So, my two questions are:

 

1. Is it safe to change the 'x2_trigger_logs' table to MyISAM as a workaround until this is addressed in X2CRM?

 

2. Can you reproduce the issue above and let us know plans for a fix?

 

 

Thank you!

 



#2 Alberto

Alberto

    Advanced Member

  • Premium Members
  • PipPipPip
  • 91 posts
  • LocationWashington

Posted 16 August 2017 - 04:54 PM

Here are some screenshots of query analytics for a 1 hour block of time running on our MySQL database for additional context:

 

Attached File  Screenshot 2017-08-16 17.23.22.png   357.87KB   0 downloads

 

Attached File  Screenshot 2017-08-16 17.24.48.png   187.5KB   0 downloads

 

 

 

 

 



#3 Alberto

Alberto

    Advanced Member

  • Premium Members
  • PipPipPip
  • 91 posts
  • LocationWashington

Posted 20 August 2017 - 07:07 PM

I went ahead and converted the 'x2_trigger_logs' table to MyISAM and compared the performance.

 

There is a significant improvement as shown below:

 

InnoDb (before):

08-11-2017 22:28:33.190000 Creating contact.
08-11-2017 22:28:34.310000 Done.

08-11-2017 22:28:34.310000 Lookup contact.
08-11-2017 22:28:34.360000 Done.

08-11-2017 22:28:34.360000 Adding tag to contact.
08-11-2017 22:28:43.750000 Done.

08-11-2017 22:28:43.750000 Adding note to contact.
08-11-2017 22:28:45.940000 Done.

08-11-2017 22:28:45.940000 Deleting contact.
08-11-2017 22:28:49.780000 Done.

Total time elapsed: 16.5868570805 seconds.

MyISAM (after):

08-21-2017 02:56:49.250000 Creating contact.
08-21-2017 02:56:49.390000 Done.

08-21-2017 02:56:49.390000 Lookup contact.
08-21-2017 02:56:49.440000 Done.

08-21-2017 02:56:49.440000 Adding tag to contact.
08-21-2017 02:56:49.640000 Done.

08-21-2017 02:56:49.640000 Adding note to contact.
08-21-2017 02:56:49.800000 Done.

08-21-2017 02:56:49.800000 Deleting contact.
08-21-2017 02:56:49.930000 Done.

Total time elapsed: 0.680815935135 seconds.

So that works around the issue for us until X2CRM application code can be updated to modify the slow queries.

 

I just wanted to share this in case anyone else runs into this issue.

 



#4 that0n3guy

that0n3guy

    Advanced Member

  • Premium Members
  • PipPipPip
  • 284 posts

Posted 12 March 2019 - 09:56 AM

Have you had any issues since you've done this?   I have the same issue with `select count(*) from x2_trigger_logs`. 



#5 that0n3guy

that0n3guy

    Advanced Member

  • Premium Members
  • PipPipPip
  • 284 posts

Posted 12 March 2019 - 10:07 AM

I just tried this on dev, I got "Error Code: 1217. Cannot delete or update a parent row: a foreign key constraint fails"... which means I'd have to remove some foreign keys... I don't know how yii works and it may need those...

 

Did you have to do this Alberto?



#6 jack

jack

    Newbie Member

  • Moderators
  • 26 posts

Posted 12 March 2019 - 12:52 PM

Hi Alberto, 

 

Can I get some more info about your set up, is your database on the same server that you have you X2 instillation?

 

-Jack



#7 Attila

Attila

    Advanced Member

  • Members
  • PipPipPip
  • 146 posts
  • LocationJohannesburg, South Africa

Posted 13 March 2019 - 07:25 AM

Hi Alberto, 

 

Can I get some more info about your set up, is your database on the same server that you have you X2 instillation?

 

-Jack

 

Jack

 

Alberto has not been online for almost 1 year, 

 

However  there are a few of us looking to speed up our databases what can you tell us ?

 

Attila   


Never allow waiting to become a habit. Live your dreams & take risks. Life is happening NOW !






Also tagged with one or more of these keywords: mysql, performance, innodb, myisam, tagging, slow query

0 user(s) are reading this topic

0 members, 0 guests, 0 anonymous users