LinuxMCE Forums

General => Users => Topic started by: Viking on November 09, 2009, 04:33:11 pm

Title: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 09, 2009, 04:33:11 pm
Hi,

on my core server one of the the AMD e5050 (dualcore) cores max out with 100% when the mysql queries for UpdateMedia are running.

Is that normal ?

I am working for a danish company that has got a lot of really good database people - also ones that are specialized on database optimizing. I could try get them to optimize some of the queries if you like ?
If so, could you point me to a place where I can find those queries ? Or just send them to me ?

The /home/public/data directories at the moment only contains the following amount of files - which I dont considder as much.
pvr : 1979
audio : 1442
video : 580



From /var/log/pluto/UpdateMedia.log
Code: [Select]
10      11/09/09 16:15:07.135           MediaState::LoadDbInfo ready to run big query <0xb52fdb90>
top
Code: [Select]
top - 16:16:01 up 1 day, 21:22,  2 users,  load average: 1.11, 1.01, 1.03
Tasks: 253 total,   1 running, 252 sleeping,   0 stopped,   0 zombie
Cpu0  : 87.0%us,  8.6%sy,  0.7%ni,  3.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  4.0%us,  3.3%sy,  4.0%ni, 80.8%id,  5.6%wa,  0.7%hi,  1.7%si,  0.0%st
Mem:   3371624k total,  2271536k used,  1100088k free,    60104k buffers
Swap:  4008208k total,     5736k used,  4002472k free,  1308160k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 6212 mysql     20   0  243m 164m 5936 S   93  5.0   1215:56 mysqld
25026 root      39  19 79908  31m 6620 S    5  0.9 121:11.69 UpdateMedia
19134 root      20   0 86768  36m  14m S    3  1.1   1:04.78 Photo_Screen_Sa
18286 mythtv    20   0  391m  81m  11m S    1  2.5 115:25.43 mythbackend

Title: Re: UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jimbodude on November 09, 2009, 04:50:25 pm
Yes, this is "normal".  The queries are in dire need of optimization...
Title: Re: UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 09, 2009, 05:35:57 pm
Hi,

found it in src/UpdateMedia/MediaState.cpp

But decided to go for MySQL "log-slow-queries" - that gave me this. It examins 215 mio. rows - holy shit.


Code: [Select]
# Time: 091109 17:05:38
# User@Host: root[root] @ localhost []
# Query_time: 53  Lock_time: 0  Rows_sent: 20889  Rows_examined: 215591614
use pluto_media;
SELECT PK_File, Path, Filename, INode,
MAX(PSC_MOD) As CurrentDbAttrDate,
(1000000 * SUM(BOOKMARKS) + 10000 * SUM(ATTRIBUTES) + 100 * SUM(LONG_ATTRIBUTES) + SUM(PICTURES)) AS CurrentDbAttrCount,
(SUM(ATTRIBUTES) + SUM(LONG_ATTRIBUTES)) AS HasAttributes,
AttrDate AS OldDbAttrDate, AttrCount AS OldDbAttrCount, ModificationDate AS OldFileDate,
Source
FROM
(
        (
                SELECT PK_File, Path, Filename, INode, Source, Missing,
                        AttrDate, AttrCount, ModificationDate,
                        MAX(IF(Bookmark.psc_mod IS NULL,CAST('0000-00-00 00:00:00' AS DATE), Bookmark.psc_mod)) AS PSC_MOD,
                        COUNT(Bookmark.PK_Bookmark) AS BOOKMARKS,
                        0 AS ATTRIBUTES, 0 AS LONG_ATTRIBUTES, 0 AS PICTURES
                FROM File
                LEFT JOIN Bookmark ON Bookmark.FK_File = PK_File
                WHERE 1 = 1 AND (Path LIKE '/home/public/data%' OR (Path = '/home/public' AND Filename = 'data' )  OR Path LIKE '/home/user_1/data%' OR (Path = '/home/user_1' AND Filename = 'data' )  OR Path LIKE '/home/user_2/data%' OR (Path = '/home/user_2' AND Filename = 'data' )  OR Path LIKE '/home/user_3/data%' OR (Path = '/home/user_3' AND Filename = 'data' )  )  AND Missing = 0
                GROUP BY PK_File, Path, Filename, INode,  AttrDate, AttrCount, ModificationDate
        )
UNION
        (
                SELECT PK_File, Path, Filename, INode, Source, Missing,
                        AttrDate, AttrCount, ModificationDate,
                        MAX(IF(Attribute.psc_mod IS NULL,CAST('0000-00-00 00:00:00' AS DATE), Attribute.psc_mod)) AS PSC_MOD,
                        0 AS BOOKMARKS,
                        COUNT(PK_Attribute) AS ATTRIBUTES,
                        0 AS LONG_ATTRIBUTES, 0 AS PICTURES
                FROM File
                LEFT JOIN File_Attribute ON File_Attribute.FK_File = PK_File
                LEFT JOIN Attribute ON File_Attribute.FK_Attribute = PK_Attribute
                WHERE 1 = 1 AND (Path LIKE '/home/public/data%' OR (Path = '/home/public' AND Filename = 'data' )  OR Path LIKE '/home/user_1/data%' OR (Path = '/home/user_1' AND Filename = 'data' )  OR Path LIKE '/home/user_2/data%' OR (Path = '/home/user_2' AND Filename = 'data' )  OR Path LIKE '/home/user_3/data%' OR (Path = '/home/user_3' AND Filename = 'data' )  )  AND Missing = 0
                GROUP BY PK_File, Path, Filename, INode,  AttrDate, AttrCount, ModificationDate
        )
UNION
        (
                SELECT PK_File, Path, Filename, INode, Source, Missing,
                        AttrDate, AttrCount, ModificationDate,
                        MAX(IF(LongAttribute.psc_mod IS NULL,CAST('0000-00-00 00:00:00' AS DATE), LongAttribute.psc_mod)) AS PSC_MOD,
                        0 AS BOOKMARKS, 0 AS ATTRIBUTES,
                        COUNT(PK_LongAttribute) AS LONG_ATTRIBUTES,
                        0 AS PICTURES
                FROM File
                LEFT JOIN LongAttribute ON LongAttribute.FK_File = PK_File
                WHERE 1 = 1 AND (Path LIKE '/home/public/data%' OR (Path = '/home/public' AND Filename = 'data' )  OR Path LIKE '/home/user_1/data%' OR (Path = '/home/user_1' AND Filename = 'data' )  OR Path LIKE '/home/user_2/data%' OR (Path = '/home/user_2' AND Filename = 'data' )  OR Path LIKE '/home/user_3/data%' OR (Path = '/home/user_3' AND Filename = 'data' )  )  AND Missing = 0
                GROUP BY PK_File, Path, Filename, INode,  AttrDate, AttrCount, ModificationDate
        )
UNION
        (
                SELECT PK_File, Path, Filename, INode, Source, Missing,
                        AttrDate, AttrCount, ModificationDate,
                        MAX(IF(Picture_File.psc_mod IS NULL,CAST('0000-00-00 00:00:00' AS DATE), Picture_File.psc_mod)) AS PSC_MOD,
                        0 AS BOOKMARKS, 0 AS ATTRIBUTES, 0 AS LONG_ATTRIBUTES,
                        COUNT(FK_Picture) AS PICTURES
                FROM File
                LEFT JOIN Picture_File ON Picture_File.FK_File = PK_File
                WHERE 1 = 1 AND (Path LIKE '/home/public/data%' OR (Path = '/home/public' AND Filename = 'data' )  OR Path LIKE '/home/user_1/data%' OR (Path = '/home/user_1' AND Filename = 'data' )  OR Path LIKE '/home/user_2/data%' OR (Path = '/home/user_2' AND Filename = 'data' )  OR Path LIKE '/home/user_3/data%' OR (Path = '/home/user_3' AND Filename = 'data' )  )  AND Missing = 0
                GROUP BY PK_File, Path, Filename, INode, AttrDate, AttrCount, ModificationDate
        )
) AS FILE_UNION
WHERE 1 = 1 AND (Path LIKE '/home/public/data%' OR (Path = '/home/public' AND Filename = 'data' )  OR Path LIKE '/home/user_1/data%' OR (Path = '/home/user_1' AND Filename = 'data' )  OR Path LIKE '/home/user_2/data%' OR (Path = '/home/user_2' AND Filename = 'data' )  OR Path LIKE '/home/user_3/data%' OR (Path = '/home/user_3' AND Filename = 'data' )  )  AND Missing = 0
GROUP BY PK_File, Path, Filename, INode, AttrDate, AttrCount, ModificationDate;



Are there any other queries that are not so good ? Video/audio list queres or something like that ?

Greetings
Viking

Title: Re: UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 13, 2009, 04:47:44 pm
Hi,

OK we need some indexes on the Database ;)

Before :
19495 rows in set (1 min 23.67 sec)

After :
19821 rows in set (8.56 sec)

I assume the different number of rows has to do with that it was scanning pictures while I did the first run. But maybe on of yiu can confirm that there is no difference if you disable UpdateMedia while doing it :
/usr/pluto/bin/UpdateMediaDaemonControl.sh -disable


here is what to do :

ALTER TABLE `pluto_media`.`File` ADD INDEX  `FatGroupBy`(`PK_File`,`Path`,`Filename`,`INode`,`AttrDate`,`AttrCount`,`ModificationDate`)

ALTER TABLE `pluto_media`.`Bookmark` ADD INDEX `FK_File`(`FK_File`);
ALTER TABLE `pluto_media`.`LongAttribute` ADD INDEX `FK_File`(`FK_File`);

Greetings
Viking
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jimbodude on November 13, 2009, 05:07:46 pm
...well that's not very hard...  Nice find.

Can you put that on a ticket so it gets in the code?
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that norm
Post by: Viking on November 13, 2009, 05:13:56 pm

I'll do that if someone confirms that there is no difference between rows before and after the change ;)

Viking
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that norm
Post by: niz23 on November 13, 2009, 10:59:45 pm
Viking,

I'll do that if someone confirms that there is no difference between rows before and after the change ;)

Viking

Nice find.
This is a huge performance boost for a simple change.


I took the liberty to add this to trac so we can track what is done to MySQL considering optimizations. See ticket 439.

/niz23
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 14, 2009, 06:57:13 pm
I tried this on my production system with about 41000 rows in the pluto_media table.

The indexes have reduced the period of time mysqld pegs my processor at 100%.

I monitor my core with monitorix and rrdtool, it's a P4 2.8G hyperthreaded cpu with 1GB ram.  It looks like adding the indexes created an average reduction of ~7% kernel usage, load average has dropped from about 1.0-1.1 average to 0.6-0.7 average.  IOWaits have also been cut in half of what they were.  The one day change is noticeable looking at my week and month summary charts.  I'm going to keep my eye on it to see if it's consistent.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that norm
Post by: Viking on November 15, 2009, 09:23:32 pm
Viking,

I'll do that if someone confirms that there is no difference between rows before and after the change ;)

Viking

Nice find.
This is a huge performance boost for a simple change.


I took the liberty to add this to trac so we can track what is done to MySQL considering optimizations. See ticket 439.

/niz23

Great, as I can see it will already be included in the next beta :)

If there is more SQL that you need someone to look at, feel free to PM or mail me.

Greetings
Viking
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jimbodude on November 16, 2009, 03:56:43 pm
Have you had a chance to look at the rest of the tables?  Maybe others also do not have indexes, or have the wrong ones?

Really a great find, thank you.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: niz23 on November 16, 2009, 07:48:12 pm
Best way to find things to optimize is to identify slow queries as Viking have already done.
If any of you want to do it feel free to post optimizations here.
When a slow query is found post them here or even better identify where in the code they come from so that we can look at sql code optimization too.

To start with identify queries that take more than 10s to complete.
When we have fixed those we can lower it to 5s.

There´s other ways to optimize mysql too. But as I´m no mysql expert I don´t know how to tune it´s query cache etc.
If someone do. Please tell us what can be done to make queries faster.

/niz23
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 16, 2009, 08:31:14 pm
I was looking at query_cache a little last night.  Most of the use/config seems transparent and efficiencies come by writing less frequently to tables.  Essentially a cached query is dropped from the cache when a write is made to a table used in the cached query.

Example: Queries that bring up the Audio/Video file lists from orbiter execute in about 7s when not in the query_cache and in about 0.5s when they are in the query_cache (on my system).  Some of these large queries are not cached for enough time (because of a write to a table used in the query) to make them really useful (like the audio/video file lists).  Update media may be writing to the media tables even when media has not changed, which is clearing these queries from the cache (I havn't even begun to look at updatemedia).

I have not looked past this yet but was intrigued by the initial improvements from Viking's index additions and did a little bit of poking around.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: colinjones on November 16, 2009, 09:04:12 pm
phenigma

are you saying that most of the time calling up media grids on your system takes around 7 seconds?

How many media files/entries in pluto_media.file do you have?

My experience is that the first time I call up the media grids after a reload, they are marginally slower... say 2s max, then from then on they are extremely nippy! I don't get a sense at all that SQL is the bottleneck in my system. Interestingly, reloading the Router does not restart MySQL nor can I think of any reason it would be writing to tables at that point so the cache should be intact over a reload.... I assumed it more more the orbiter code itself, perhaps caching thumbnails, or other activities.

Anyway, my underlying point is, if I'm not doing anything, it certainly doesn't appear that UpdateMedia running in anyway impacts cache performance by flushing it. Although I do note there is still (0710, and 0810 I think) a bug in UM that means when you set a thumbnail for a folder this causes UM constantly to redetect this as a change, and perhaps that is constantly writing into the database.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jondecker76 on November 16, 2009, 10:52:21 pm
With about 800 videos, on my system it takes probably 10 seconds to complete the query and populate the datagrid (this has been the case both in 0710 and 0810). Mysql definitely seems to be a bottleneck on my system!
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 17, 2009, 12:14:06 am
Without actually looking, I think I have about 600 videos and around 800 or 900 artists in my audio folders.

The response time is the same regardless of the orbiter I use (n800,webdt,onscreen), UI1 or 2, core or MD.  It takes about 7 seconds from click/touch to display of the datagrid.  When I do this the query is cached by query_cache in mysql and choosing audio/video again immediately is very responsive from click/touch to display of the datagrid, 0.5 seconds on my windows orbiter to about 3 seconds on my WebDT.  Response is the same now as it was under 0710, I'm currently running 0810 Alpha 2.37.

The responsiveness lasts for a couple minutes, until the query is removed from the cache, and then it takes about 7 seconds to re-rerun the query and re-store the results in mysql query_cache for another couple of minutes.  I can only assume that UpdateMedia is writing to the table but I'm speculating.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 17, 2009, 12:01:54 pm
Hi,

don't have much time at the moment. But would like to give you some hints for going on :)
If you have queries where you can't find out what to do send me a PM. I will also try to follow this. But I have got lots of work and three sick kids, so not much time.


If you would like to find out which are the slow queries, activate this (remove the #) in /etc/mysql/my.cnf :

#log_slow_queries       = /var/log/mysql/mysql-slow.log
#long_query_time = 10
#log-queries-not-using-indexes


Note : "long_query_time" means the time that a query should run before it gets into the logfile. A good start is probably 10 seconds, but for some things you can also go lower ;)

And do a

/etc/init.d/mysql restart


After that use try to show the video datagrid and take a look in the "/var/log/mysql/mysql-slow.log" logfile.
You can the take the query from there an execute it on it's own.

I di not have time to look at the UpdateMedia query after the optimizing, but before it use 215 millions rows to get it done. That will prbably clear the query_cache ;)

You should not run you system permanently with this turned on though. The log will grow quite big.


-------

To find out what is actually done use this :

EXPLAIN EXTENDED <query>;
SHOW WARNINGS;


In the Update Media query that looked like this. As you can see in "before" it uses temp tables (using temporary) and "after" it is using indexes. That is a lot faster :)
So if a query uses temp tables , we can probably improve performance with indexes.


BEFORE :

+----+--------------+----------------+--------+-----------------+---------+---------+-----------------------------------------+-------+----------------------------------------------+
| id | select_type  | table          | type   | possible_keys   | key     | key_len | ref                                     | rows  | Extra                                        |
+----+--------------+----------------+--------+-----------------+---------+---------+-----------------------------------------+-------+----------------------------------------------+
|  1 | PRIMARY      | <derived2>     | ALL    | NULL            | NULL    | NULL    | NULL                                    | 35553 | Using where; Using temporary; Using filesort |
|  2 | DERIVED      | File           | ALL    | Path,Filename   | NULL    | NULL    | NULL                                    | 33257 | Using where; Using temporary; Using filesort |
|  2 | DERIVED      | Bookmark       | ALL    | NULL            | NULL    | NULL    | NULL                                    |   170 |                                              |
|  3 | UNION        | File           | ALL    | Path,Filename   | NULL    | NULL    | NULL                                    | 33257 | Using where; Using temporary; Using filesort |
|  3 | UNION        | File_Attribute | ref    | PRIMARY,FK_File | FK_File | 4       | pluto_media.File.PK_File                |     2 | Using index                                  |
|  3 | UNION        | Attribute      | eq_ref | PRIMARY         | PRIMARY | 4       | pluto_media.File_Attribute.FK_Attribute |     1 |                                              |
|  4 | UNION        | File           | ALL    | Path,Filename   | NULL    | NULL    | NULL                                    | 33257 | Using where; Using temporary; Using filesort |
|  4 | UNION        | LongAttribute  | ALL    | NULL            | NULL    | NULL    | NULL                                    |  2424 |                                              |
|  5 | UNION        | File           | ALL    | Path,Filename   | NULL    | NULL    | NULL                                    | 33257 | Using where; Using temporary; Using filesort |
|  5 | UNION        | Picture_File   | ref    | FK_File         | FK_File | 4       | pluto_media.File.PK_File                |     1 |                                              |
| NULL | UNION RESULT | <union2,3,4,5> | ALL    | NULL            | NULL    | NULL    | NULL                                    |  NULL |                                              |
+----+--------------+----------------+--------+-----------------+---------+---------+-----------------------------------------+-------+----------------------------------------------+
11 rows in set, 1 warning (1 min 10.85 sec)


AFTER :

+----+--------------+----------------+--------+-----------------+------------+---------+-----------------------------------------+-------+----------------------------------------------+
| id | select_type  | table          | type   | possible_keys   | key        | key_len | ref                                     | rows  | Extra                                        |
+----+--------------+----------------+--------+-----------------+------------+---------+-----------------------------------------+-------+----------------------------------------------+
|  1 | PRIMARY      | <derived2>     | ALL    | NULL            | NULL       | NULL    | NULL                                    | 60213 | Using where; Using temporary; Using filesort |
|  2 | DERIVED      | File           | index  | Path,Filename   | FatGroupBy | 546     | NULL                                    | 32007 | Using where                                  |
|  2 | DERIVED      | Bookmark       | ref    | FK_File         | FK_File    | 5       | pluto_media.File.PK_File                |     1 |                                              |
|  3 | UNION        | File           | index  | Path,Filename   | FatGroupBy | 546     | NULL                                    | 32007 | Using where                                  |
|  3 | UNION        | File_Attribute | ref    | PRIMARY,FK_File | FK_File    | 4       | pluto_media.File.PK_File                |     2 | Using index                                  |
|  3 | UNION        | Attribute      | eq_ref | PRIMARY         | PRIMARY    | 4       | pluto_media.File_Attribute.FK_Attribute |     1 |                                              |
|  4 | UNION        | File           | index  | Path,Filename   | FatGroupBy | 546     | NULL                                    | 32007 | Using where                                  |
|  4 | UNION        | LongAttribute  | ref    | FK_File         | FK_File    | 5       | pluto_media.File.PK_File                |     1 |                                              |
|  5 | UNION        | File           | index  | Path,Filename   | FatGroupBy | 546     | NULL                                    | 32007 | Using where                                  |
|  5 | UNION        | Picture_File   | ref    | FK_File         | FK_File    | 4       | pluto_media.File.PK_File                |     1 |                                              |
| NULL | UNION RESULT | <union2,3,4,5> | ALL    | NULL            | NULL       | NULL    | NULL                                    |  NULL |                                              |
+----+--------------+----------------+--------+-----------------+------------+---------+-----------------------------------------+-------+----------------------------------------------+
11 rows in set, 1 warning (7.92 sec)

--------

Some more things to try.

mysql>set profiling=1
mysql> Do things ( run qurey)
mysql>show profiles;
 
and get some more details for what we did :
 
mysql>show profile [all|block io|context switches|ipc|page faults|source|swaps] for query X;
 
 
Documentation: http://dev.mysql.com/doc/refman/5.0/en/show-profiles.html


--------

Last, iIf we use temp tables, we could try getting the to fit into memory - but better would be not to need that :
http://dev.mysql.com/doc/refman/5.1/en/server-system-variables.html#sysvar_max_heap_table_size
http://dev.mysql.com/doc/refman/5.1/en/server-system-variables.html#sysvar_tmp_table_size

That did not help anything on the UpdateMedia query - i tried it.


Greetings
Viking
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 17, 2009, 01:43:59 pm
Thanks Viking, I'll do some more investigating when I get home from work.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: colinjones on November 17, 2009, 09:37:31 pm
hmmm... I don't get it, guys...

My data grids populate pretty much instantly all the time. I have about 1750 avi files, and probably lots more as mkv, mp4, etc. I usually use Filename sort mode which obviously isn't going to run the same big queries, so I just tested using Title... same results. It populates in like 0.5 seconds.

I tried /etc/init.d/mysql restart, then tried it again (on the basis that presumably restarting the SQL server would flush any caches) the first time it seemed to take about 1 second to populate, and subsequent retries back to 0.5 seconds. I note that only a relatively small percentage of my media files have artwork assigned, in case that slows things down (wouldn't think so, as it should only be retrieving the artwork for the tiles that are actually in the display at the time, so probably no more than 20 images)

When I type /etc/init.d/mysql status the SQL server had been running for 25 days and had executed about 12 million queries (ave around 5 per second), but only about 600 were considered "long". That being said, the cnf file has the "long" query defined as 2 seconds commented out, so I'm not sure how it is determining which queries are long!

Obviously I don't want my queries to take as long as yours! But I'm a bit baffled as to why they don't. (using 0710 btw)
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jimbodude on November 17, 2009, 09:53:35 pm
...You must be doing something special...  I'm looking at a pretty noticeable delay, and I have much less than 1000 video files...  Mine are all fully tagged, mostly ISOs, with cover-art.  I haven't timed it, but I'd say it's taking at least 3-5 seconds to get the orbiter updated.  Not sure if that's an SQL issue or not, though - it performs much better with my new Wireless AP, before I was looking at about 10 seconds...  The web orbiter is also noticeably slow, but harder to put my finger on how long that takes.  I don't usually use the on-screen orbiter, so I can't compare to that right now.  I'll look into it more if someone needs more data.

In 14 days of uptime, I have 9.6 million queries, average of 7.6 query/second, 1 slow query.  Using whatever the default is for slow query time.  The slow query log doesn't exist.  This is in 0810, last updated a week or two ago.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 17, 2009, 10:17:31 pm
Artwork may be a contributing factor then, almost all of my media has artwork.  I can see the memory being allocated for the query in mysql when I select Audio or Video button in orbiter (takes ~7s).  The Audio query occupies a about 570Kb in the cache on my system.  I return to the home menu and select audio, the artists now display in about 0.5s.  As I monitor the cache in mysql after a couple minutes a 570kb chunk is freed from the cache memory.  Selecting audio again takes ~7s and about 570kb is added to the query_cache.  Mysql is abosolutely removing the query from the cache every few minutes on my system.  I'm not home from work yet but I'm going to dig around a bit more when I get home.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jimbodude on November 17, 2009, 10:21:49 pm
Which orbiter are your "time to display" estimates coming from? On Screen?  I'll experiment a bit also, if I don't get in too late, and let you know what I find.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 18, 2009, 01:39:50 am
Predominantly my Windows Orbiter.

The behaviour:
device, time uncached, time cached
WinOrbiter, ~7s, <1s (UI1)
Nokia N800, ~10s, ~3s (UI1)
WebDT 366, ~7s, ~2s (UI1)
p42.8 Core, ~7s, <1s (UI2 mask)
Zotac ION MD, ~7, <1s (UI2 mask)

When the query is executed and not present in the cache, top shows mysql using 90-100% of the processor for nearly the entire 7s time period, and it doesn't even show up as a blip in top when the query is in the cache.  I'm about to investigate some of the slow query logging options Viking pointed out and see what I can find out.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 18, 2009, 03:35:34 am
Okay, the two queries are large but I see what they're doing, they're too large to post here so I've put them on pastebin.

The audio query results from mysql-slow.log show each query took 6 seconds to execute:
# Time: 091117 19:44:46
# User@Host: root[root] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 627  Rows_examined: 117280

The video query from mysql-slow.log:
# Time: 091117 19:44:56
# User@Host: root[root] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 8594  Rows_examined: 954413

The audio query results of the EXPLAIN EXTENDED & SHOW WARNINGS> http://pastebin.com/f5efcf4a7
The video query results of the EXPLAIN EXTENDED & SHOW WARNINGS> http://pastebin.com/f711a0612

The audio and video query results clearly show temporary tables being used rather than indexes.

J
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: jimbodude on November 18, 2009, 04:37:49 am
You beat me to it... I see similar results here.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: colinjones on November 18, 2009, 08:36:20 pm
How are you determining the amount of cache space consumed by the query?

I would have assumed that the query to create the collection of files would not have also retrieved the artwork. Only once Orbiter determines how many and which files are needed for the onscreen grid would it then query and return the artwork for those files only. In which case the artwork assigned shouldn't matter.....
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: tkmedia on November 18, 2009, 08:58:48 pm
Not sure if this has any significance but after adding indexes i noticed a speed improvement in populating the grids on my web pad orbiter.

The strange thing is the text in the grid updates almost immediately then 1-2 seconds later the artwork updates.
Not sure if the delay is caused by the drawing of the graphic though.

For whatever thats worth.



Tim
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on November 19, 2009, 12:08:06 am
How are you determining the amount of cache space consumed by the query?

You can monitor the status of the query cache like this:
Code: [Select]
mysql> SHOW STATUS LIKE 'Qcache%';
+-------------------------+----------+
| Variable_name           | Value    |
+-------------------------+----------+
| Qcache_free_blocks      | 16       |
| Qcache_free_memory      | 13297728 |
| Qcache_hits             | 57112    |
| Qcache_inserts          | 5118     |
| Qcache_lowmem_prunes    | 0        |
| Qcache_not_cached       | 31260    |
| Qcache_queries_in_cache | 1951     |
| Qcache_total_blocks     | 3978     |
+-------------------------+----------+
8 rows in set (0.00 sec)

And with out the filter you can see more mysql information.
Code: [Select]
SHOW STATUS;
Quote
I would have assumed that the query to create the collection of files would not have also retrieved the artwork. Only once Orbiter determines how many and which files are needed for the onscreen grid would it then query and return the artwork for those files only. In which case the artwork assigned shouldn't matter.....

Yes, you are correct as far as I can tell.  I don't see this being artwork related with the behaviour I'm observing.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 19, 2009, 10:27:51 am
Hi,

don't have time today, but will look at it tomorrow.

What strikes me. Why is it doing this :
"AND PK_File in (37968,37996,38006, ....."

It looks like there is an query before that which sorts out the files to look at. The question is then if it makes sence to split that up in two. But maybe we should just try and optimize the query first ;)


The second thing i posted gives some more infos :

# write output to a logfile
mysql --tee=/tmp/mysql-output.log

set profiling=1;
"run query"
show profile all;

That shows where the time has gone (second row) - for example if the problem is that it creates a temp table.

Here a cutout of the UpdateMedia query - you can see that it spents quite some time with "Copying to tmp table" and does some I/O (Block_ops_out) :

Code: [Select]
| Status                         | Duration  | CPU_user  | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function         | Source_file   | Source_line |

| executing                      |  0.000004 |  0.000000 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                    | sql_select.cc |        1581 |
| Copying to tmp table           | 51.064221 | 77.472841 |   1.264079 |               746 |               23671 |            0 |         92152 |             0 |                 0 |                 0 |              2313 |     0 | exec                    | sql_select.cc |        1721 |

Not sure if that will get us further, but the more infos the better.

Greetings
Viking
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 19, 2009, 10:41:25 am
Hi again,

just did find time to find the query for my system and it puzzels me that every dvd/recording shows up not only once, but several times !? :
(there were more Evolution lies, had to remove thre to fit in 20000 chars limit)

Code: [Select]
|   46524 |  | Nyhederne                                                                                                                                          | 0 |             3 | 4004_20091117185800.mpg                                                               | NULL                |
|   46524 |  |                                                                                                                                                    | 0 |             3 | 4004_20091117185800.mpg                                                               | NULL                |
|   46524 |  |                                                                                                                                                    | 0 |             3 | 4004_20091117185800.mpg                                                               | NULL                |
|   46524 |  |                                                                                                                                                    | 0 |             3 | 4004_20091117185800.mpg                                                               | NULL                |
|   46524 |  |                                                                                                                                                    | 0 |             3 | 4004_20091117185800.mpg                                                               | NULL                |
|   42612 |  | Evolution                                                                                                                                          | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |
|   42612 |  |                                                                                                                                                    | 0 |          NULL | Evolution.ISO                                                                         | 2009-11-13 22:14:32 |

Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: chriss on November 19, 2009, 11:39:16 am
Hi Viking,

just did find time to find the query for my system and it puzzels me that every dvd/recording shows up not only once, but several times !? :

there is a command to prevent duplicate lines in result sets from mysql. Just try to do a "SELECT DISTINCT ..." instead of "SELECT ...". Reducing the result set of a query does also reduce resource usage, especially if the results are used to start another query.

Quote
What strikes me. Why is it doing this :
"AND PK_File in (37968,37996,38006, ....."

It looks like there is an query before that which sorts out the files to look at. The question is then if it makes sence to split that up in two. But maybe we should just try and optimize the query first.

Using nested queries should even speed up the process because the results do not have to be tranferred back and forth, i.e. try something like "SELECT ... FROM ... WHERE ... AND PK_File in (SELECT DISTINCT FK_File FROM ....)".

br,
/chriss
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: colinjones on November 19, 2009, 09:18:00 pm
It almost looks like the long list of PK_Files is the subset of media files of the particular MediaType that the data grid is to be for. eg all the media files of "LinuxMCE Video File" type, so the query only returns video files.

That doesn't seem very efficient (intuition only here!). If that is the purpose wouldn't it have been better to have used the EK_MediaType key in the pluto_media.File table and just use a normal matching Where clause?

Or is that set of PK_Files something else entirely? hmmm.... perhaps it is the subset of files it has determined are currently "available" based on which media sources are currently online/connected to the LMCE network?
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on November 19, 2009, 09:23:55 pm
Someone will have to dig the code to find out ;)

Viking
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: phenigma on February 19, 2010, 10:31:23 pm
So I'd been unhappy with my queries performances following a re-install in January and it turns out the indexes built in this thread are not being applied to new installations.  I have added at least one more index now which has added another significant speed-up to some of my queries and I've made some adjustments to query_cache which have also significantly sped-up some of my queries and reduced the load on my core.  I'm hopefully going to wrap this all up on a dev system and submit a patch in about 1.5 weeks (when I have a week off). 

There has been some discussion in IRC about optimizations regarding the video query after doing tv episode tagging. 

Has anyone else figured out any other optimizations during their playing?  I'd love to incorporate anything/everything I can.

J.
Title: Re: [SOLVED] - UpdateMedia mysql queries takes 100% CPU on a core - is that normal ?
Post by: Viking on February 22, 2010, 09:27:21 am
Sounds good :) looking forward to that.

I had no time looking further into this. But it feels as if the queries has gone slower again :( - probably beacuse I have added more videos and pictures.

Viking