G3 beta2 large import issues

[Steve Lacy]

Hi all,

I'm importing 29605 photos from g2 to g3 as we speak.  It's been running for 12+ hours now, and I've noticed at least a couple of issues with this big import.

First, I'm getting many errors in my logs that look like this:

Jul 18 13:02:49 tornado mysqld[4927]: 090718 13:02:49  InnoDB: ERROR: the age of the last checkpoint is 9433818,
Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: which exceeds the log group capacity 9433498.
Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: If you are using big BLOB or TEXT rows, you must set the
Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: combined size of log files at least 10 times bigger than the
Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: largest such row.

So, there's clearly some InnoDB issues here.   I'm concerned about the use of InnoDB because of the known growth issues with the ibdata files (they're essentially never garbage collected)  So, I expect users who have a large delete load may see substantial growth in the disk-size of their databases.  Will g3 run with the my.cnf "skip-innodb" option enabled?  (I.e. only MyISAM storage)?

Secondly, I'm looking at mysql-slow.log, and seeing a *very* large update of the "caches" tables with a text description of the actions taken thus far.  Take a look at this:

mysql> select id, tags, expiration, length(cache) from caches;
+----+-----------------------+------------+---------------+
| id | tags                  | expiration | length(cache) |
+----+-----------------------+------------+---------------+
|  1 | <css>                 | 1250428841 |         58231 |
|  2 | <css>,<gzip>          | 1250428841 |         11668 |
|  3 | <javascript>          | 1250428841 |        289956 |
|  4 | <javascript>,<gzip>   | 1250428842 |         78219 |
|  5 | <css>                 | 1250429101 |         60671 |
|  6 | <css>,<gzip>          | 1250429101 |         12057 |
|  7 | <javascript>          | 1250429101 |        271290 |
|  8 | <javascript>,<gzip>   | 1250429101 |         75301 |
|  9 | <task>,<log>,<import> | 1250543332 |       1209184 |
| 10 | <javascript>          | 1250430126 |        291188 |
| 11 | <javascript>,<gzip>   | 1250430127 |         78566 |
| 12 | <javascript>          | 1250430165 |        296760 |
| 13 | <javascript>,<gzip>   | 1250430165 |         80412 |
| 14 | <css>                 | 1250431542 |         57469 |
| 15 | <css>,<gzip>          | 1250431542 |         11539 |
| 16 | <javascript>          | 1250431542 |        288964 |
| 17 | <javascript>,<gzip>   | 1250431542 |         78104 |
+----+-----------------------+------------+---------------+
17 rows in set (0.10 sec)

So you've got a row there (id=9) that's 1.2MB and growing.  The "cache" value looks like this:

[...]
View count updated: 86
Imported photo: ''

View count updated: 81
Imported photo: ''

View count updated: 84
Imported photo: ''

View count updated: 74
Imported photo: ''

View count updated: 106
Imported photo: ''
[...]

And each new photo seems to be doing a read/modify/write operation on that row.  Ugh.

My import has slowed down substantially since it started, and is now running at ~1 photo per second, so it'll be another hour or so before it's done (assuming it doesn't get much slower than that).  When I'm done, I'll hammer it a bit and see how it looks. 

Steve

------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge  
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize  
details at: http://p.sf.net/sfu/Challenge
__[ g a l l e r y - d e v e l ]_________________________

[ list info/archive --> http://gallery.sf.net/lists.php ]
[ gallery info/FAQ/download --> http://gallery.sf.net ]

[Bharat Mediratta]

Stephen Lacy wrote:

> First, I'm getting many errors in my logs that look like this:
>
> Jul 18 13:02:49 tornado mysqld[4927]: 090718 13:02:49  InnoDB: ERROR:
> the age of the last checkpoint is 9433818,
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: which exceeds the log
> group capacity 9433498.
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: If you are using big BLOB
> or TEXT rows, you must set the
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: combined size of log files
> at least 10 times bigger than the
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: largest such row.
>
> So, there's clearly some InnoDB issues here.   I'm concerned about the
> use of InnoDB because of the known growth issues with the ibdata files
> (they're essentially never garbage collected)  So, I expect users who
> have a large delete load may see substantial growth in the disk-size of
> their databases.  Will g3 run with the my.cnf "skip-innodb" option
> enabled?  (I.e. only MyISAM storage)?

It can.  I was aiming for simplicity and from what I read, InnoDB is
better than MyISAM in most ways so it was easiest to just hardcode
InnoDB.  It would be easy to allow users to switch in the installer, but
I'm loathe to add any more options there.  I'm open to ideas and am not
very familiar with skip-innodb.

> Secondly, I'm looking at mysql-slow.log, and seeing a *very* large
> update of the "caches" tables with a text description of the actions
> taken thus far.  Take a look at this:
...
> |  9 | <task>,<log>,<import> | 1250543332 |       1209184 |
> 17 rows in set (0.10 sec)

Ouch.  Looks like our G2 Import logging is overzealous.  It should only
be logging errors, not complete status.  I've just pushed a change to
fix that.  It won't help you, but it'll help the next guy :-)

> My import has slowed down substantially since it started, and is now
> running at ~1 photo per second, so it'll be another hour or so before
> it's done (assuming it doesn't get much slower than that).  When I'm
> done, I'll hammer it a bit and see how it looks.

At the end of the import, we should probably optimize all tables.  I'll
be curious to hear how your performance is.  I haven't done an
optimizing pass in about a month so I wouldn't be surprised if our query
count and render time has crept back up a bit.

-Bharat

------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge  
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize  
details at: http://p.sf.net/sfu/Challenge
__[ g a l l e r y - d e v e l ]_________________________

[ list info/archive --> http://gallery.sf.net/lists.php ]
[ gallery info/FAQ/download --> http://gallery.sf.net ]

[Steve Lacy]

Attached are the slow query logs.  (Let me know if these don't come through the mailing list properly).  The top offenders of total query time are:

Count: 30167  Time=0.33s (10065s)  Lock=0.00s (2s)  Rows=0.0 (0), root[root]@loc
alhost
  UPDATE items SET `left` = `left` + N WHERE `left` >= N

Count: 30167  Time=0.27s (7996s)  Lock=0.00s (3s)  Rows=0.0 (0), root[root]@loca
lhost
  UPDATE items SET `right` = `right` + N WHERE `right` >= N

Count: 31312  Time=0.07s (2347s)  Lock=0.00s (0s)  Rows=1.0 (31292), root[root]@
localhost
  SELECT *
  FROM (`caches`)
  WHERE `key` = 'S'

Count: 31180  Time=0.06s (1915s)  Lock=0.02s (486s)  Rows=0.0 (0), root[root]@lo
calhost
  UPDATE `caches` SET `tags` = 'S', `expiration` = N, `cache` = 'S' WHERE `key`
= 'S'

Count: 30167  Time=0.04s (1106s)  Lock=0.00s (1s)  Rows=1.0 (30167), root[root]@
localhost
  SELECT MAX(weight) as max_weight
  FROM (`items`)
  LIMIT N, N

So, thats a total of about 23500 seconds, or 6.5 hours spent in MySQL.   :)   Also note that there are some other non-gallery3 queries in there, but likely they're very low on the list.  I don't think there's anything "private" therein. :)

Steve

On Sat, Jul 18, 2009 at 4:15 PM, Bharat Mediratta <bharat@...> wrote:

Stephen Lacy wrote:
> First, I'm getting many errors in my logs that look like this:
>
> Jul 18 13:02:49 tornado mysqld[4927]: 090718 13:02:49  InnoDB: ERROR:
> the age of the last checkpoint is 9433818,
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: which exceeds the log
> group capacity 9433498.
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: If you are using big BLOB
> or TEXT rows, you must set the
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: combined size of log files
> at least 10 times bigger than the
> Jul 18 13:02:49 tornado mysqld[4927]: InnoDB: largest such row.
>
> So, there's clearly some InnoDB issues here.   I'm concerned about the
> use of InnoDB because of the known growth issues with the ibdata files
> (they're essentially never garbage collected)  So, I expect users who
> have a large delete load may see substantial growth in the disk-size of
> their databases.  Will g3 run with the my.cnf "skip-innodb" option
> enabled?  (I.e. only MyISAM storage)?

It can.  I was aiming for simplicity and from what I read, InnoDB is
better than MyISAM in most ways so it was easiest to just hardcode
InnoDB.  It would be easy to allow users to switch in the installer, but
I'm loathe to add any more options there.  I'm open to ideas and am not
very familiar with skip-innodb.

> Secondly, I'm looking at mysql-slow.log, and seeing a *very* large
> update of the "caches" tables with a text description of the actions
> taken thus far.  Take a look at this:

...

> |  9 | <task>,<log>,<import> | 1250543332 |       1209184 |

> 17 rows in set (0.10 sec)

Ouch.  Looks like our G2 Import logging is overzealous.  It should only
be logging errors, not complete status.  I've just pushed a change to
fix that.  It won't help you, but it'll help the next guy :-)

> My import has slowed down substantially since it started, and is now
> running at ~1 photo per second, so it'll be another hour or so before
> it's done (assuming it doesn't get much slower than that).  When I'm
> done, I'll hammer it a bit and see how it looks.

At the end of the import, we should probably optimize all tables.  I'll
be curious to hear how your performance is.  I haven't done an
optimizing pass in about a month so I wouldn't be surprised if our query
count and render time has crept back up a bit.

-Bharat

Count: 30167  Time=0.33s (10065s)  Lock=0.00s (2s)  Rows=0.0 (0), root[root]@localhost
  UPDATE items SET `left` = `left` + N WHERE `left` >= N

Count: 30167  Time=0.27s (7996s)  Lock=0.00s (3s)  Rows=0.0 (0), root[root]@localhost
  UPDATE items SET `right` = `right` + N WHERE `right` >= N

Count: 31312  Time=0.07s (2347s)  Lock=0.00s (0s)  Rows=1.0 (31292), root[root]@localhost
  SELECT *
  FROM (`caches`)
  WHERE `key` = 'S'

Count: 31180  Time=0.06s (1915s)  Lock=0.02s (486s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `caches` SET `tags` = 'S', `expiration` = N, `cache` = 'S' WHERE `key` = 'S'

Count: 30167  Time=0.04s (1106s)  Lock=0.00s (1s)  Rows=1.0 (30167), root[root]@localhost
  SELECT MAX(weight) as max_weight
  FROM (`items`)
  LIMIT N, N

Count: 38  Time=5.95s (226s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE g2_CacheMap SET g_value=NULL, g_isEmpty=N WHERE g_userId=N AND g_timestamp < N AND g_isEmpty=N

Count: 24  Time=3.25s (78s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE g2_CacheMap SET g_value='S', g_timestamp=N, g_isEmpty=N WHERE g_key='S' AND g_userId=N AND g_itemId=N AND g_type='S'

Count: 18  Time=3.67s (66s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `items` SET `resize_width` = N, `resize_height` = N, `resize_dirty` = N, `updated` = N WHERE `id` = N

Count: 8  Time=4.00s (32s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SET insert_id=N;
  INSERT INTO `items` (`type`, `title`, `description`, `relative_path_cache`, `name`, `owner_id`, `width`, `height`, `mime_type`, `thumb_dirty`, `resize_dirty`, `sort_column`, `rand_key`, `left`, `right`, `parent_id`, `level`, `updated`, `created`, `weight`) VALUES ('S', 'S', 'S', NULL, 'S', N, N, N, 'S', N, N, 'S', N.N, N, N, N, N, N, N, N)

Count: 2  Time=13.50s (27s)  Lock=0.00s (0s)  Rows=0.0 (0), debian-sys-maint[debian-sys-maint]@localhost
  # administrator command: Refresh

Count: 97  Time=0.22s (21s)  Lock=0.00s (0s)  Rows=22848.0 (2216256), root[root]@localhost
  SELECT
  g2_Item.g_id,
  g2_Entity.g_modificationTimestamp,
  ((N - g2_Entity.g_creationTimestamp) /
  g2_Entity.g_serialNumber) as SecondsPerChange
  FROM
  g2_Item
  INNER JOIN g2_Entity ON g2_Item.g_id = g2_Entity.g_id
  INNER JOIN g2_AccessSubscriberMap
  ON g2_Item.g_id = g2_AccessSubscriberMap.g_itemId
  WHERE
  g2_AccessSubscriberMap.g_accessListId IN (N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N)
  ORDER BY g2_Entity.g_modificationTimestamp ASC

Count: 30295  Time=0.00s (21s)  Lock=0.00s (1s)  Rows=1.0 (30295), root[root]@localhost
  SELECT `access_caches`.*
  FROM (`access_caches`)
  WHERE `item_id` = N
  ORDER BY `access_caches`.`id` ASC
  LIMIT N, N

Count: 5  Time=3.20s (16s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  INSERT INTO g2_CacheMap (g_key, g_value, g_userId, g_itemId, g_type, g_timestamp, g_isEmpty) VALUES ('S','S',N,N,'S',N,N)

Count: 4  Time=3.75s (15s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `tasks` SET `state` = 'S', `status` = 'S', `percent_complete` = N, `context` = 'S', `updated` = N WHERE `id` = N

Count: 31653  Time=0.00s (13s)  Lock=0.00s (1s)  Rows=0.0 (0), root[root]@localhost
  SELECT `text`
  FROM (`comments`)
  WHERE `item_id` = N

Count: 2  Time=5.50s (11s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `sessions` SET `last_activity` = N, `data` = 'S' WHERE `session_id` = 'S'

Count: 3  Time=3.33s (10s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SET insert_id=N;
  INSERT INTO `g2_maps` (`g3_id`, `g2_id`) VALUES (N, N)

Count: 2  Time=3.50s (7s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `items` SET `thumb_width` = N, `thumb_height` = N, `thumb_dirty` = N, `resize_width` = N, `resize_height` = N, `resize_dirty` = N, `updated` = N WHERE `id` = N

Count: 31217  Time=0.00s (6s)  Lock=0.00s (1s)  Rows=1.0 (31217), root[root]@localhost
  SELECT COUNT(*) AS `records_found`
  FROM (`caches`)
  WHERE `key` = 'S'
  AND `expiration` >= N

Count: 1  Time=3.00s (3s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `items` SET `thumb_width` = N, `thumb_height` = N, `thumb_dirty` = N, `updated` = N WHERE `id` = N

Count: 1  Time=3.00s (3s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SET insert_id=N;
  INSERT INTO `exif_records` (`item_id`, `data`, `key_count`, `dirty`) VALUES (N, 'S', N, N)

Count: 1  Time=3.00s (3s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  SELECT `g2_maps`.*
  FROM (`g2_maps`)
  WHERE `g2_id` = N
  ORDER BY `g2_maps`.`id` ASC
  LIMIT N, N

Count: 2  Time=0.50s (1s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  SELECT
  iam0.g_itemId,
  COUNT(iam1.g_itemId)
  FROM
  g2_ItemAttributesMap AS iam0,
  g2_ItemAttributesMap AS iam1,
  g2_AccessSubscriberMap
  WHERE
  iam0.g_itemId IN (N)
  AND
  iam1.g_parentSequence LIKE CONCAT(iam0.g_parentSequence, iam0.g_itemId, 'S')
  AND
  iam1.g_itemId = g2_AccessSubscriberMap.g_itemId
  AND
  g2_AccessSubscriberMap.g_accessListId IN (N,,{repeated 108 times}N)
  GROUP BY
  iam0.g_itemId

Count: 6  Time=0.17s (1s)  Lock=0.00s (0s)  Rows=1.0 (6), root[root]@localhost
  SELECT
  COUNT(g2_Item.g_id)
  FROM
  g2_Entity, g2_Item, g2_AccessSubscriberMap
  WHERE
  g2_Entity.g_entityType = 'S'
  AND
  g2_Item.g_id = g2_Entity.g_id
  AND
  g2_AccessSubscriberMap.g_itemId = g2_Entity.g_id
  AND
  g2_AccessSubscriberMap.g_accessListId IN (N,,{repeated 108 times}N)

Count: 27  Time=0.04s (1s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  DELETE FROM `caches` WHERE `expiration` != N AND `expiration` <= N

Count: 13  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.9 (12), root[root]@localhost
  SELECT `items`.*
  FROM (`items`)
  WHERE `relative_path_cache` = 'S'
  LIMIT N, N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select count(N) from items

Count: 13  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=21.4 (278), root[root]@localhost
  SELECT g_property, g_sequence FROM g2_ExifPropertiesMap WHERE g_viewMode=N ORDER BY g_sequence ASC

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=42.0 (84), root[root]@localhost
  SELECT
  g2_PluginMap.g_pluginId,
  g2_PluginMap.g_active
  FROM
  g2_PluginMap
  WHERE
  g2_PluginMap.g_pluginType = 'S'

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=17.0 (17), root[root]@localhost
  select id, length(cache) from caches

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=2.0 (2), root[root]@localhost
  select * from users

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  SELECT COUNT(*) AS `records_found`
  FROM (`items`)

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select count(N) from caches

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  DELETE FROM `graphics_rules` WHERE `module_name` = 'S' AND `target` = 'S' AND `operation` = 'S' AND N=N

Count: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=2.0 (6), root[root]@localhost
  SELECT `groups`.*
  FROM (`groups`)
  ORDER BY `groups`.`id` ASC

Count: 20  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=2.0 (40), root[root]@localhost
  SELECT
  g2_TkPropertyMimeTypeMap.g_toolkitId
  FROM
  g2_TkPropertyMap,
  g2_TkPropertyMimeTypeMap
  WHERE
  g2_TkPropertyMap.g_name = g2_TkPropertyMimeTypeMap.g_propertyName
  AND
  g2_TkPropertyMimeTypeMap.g_mimeType = 'S'
  AND
  g2_TkPropertyMap.g_name = 'S'

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SELECT `comments`.*
  FROM (`comments`)
  ORDER BY `created` DESC
  LIMIT N, N

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `items` SET `resize_dirty` = N WHERE N

Count: 4  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=780.0 (3120), root[root]@localhost
  SELECT
  g2_AlbumItem.g_id,
  g2_ItemAttributesMap.g_parentSequence,
  g2_ItemAttributesMap.g_orderWeight
  FROM
  g2_AlbumItem, g2_ItemAttributesMap, g2_AccessSubscriberMap
  WHERE
  g2_AlbumItem.g_id = g2_ItemAttributesMap.g_itemId
  AND
  g2_ItemAttributesMap.g_parentSequence LIKE 'S'
  AND
  g2_AlbumItem.g_id = g2_AccessSubscriberMap.g_itemId
  AND
  g2_AccessSubscriberMap.g_accessListId IN (N,,{repeated 108 times}N)
  ORDER BY
  g2_ItemAttributesMap.g_parentSequence,
  g2_ItemAttributesMap.g_orderWeight

Count: 46  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=69.6 (3201), root[root]@localhost
  SELECT DISTINCT
  g2_AccessMap.g_accessListId
  FROM
  g2_AccessMap
  WHERE
  g2_AccessMap.g_userOrGroupId IN (N,N)
  AND
  g2_AccessMap.g_permission & N = N

Count: 5  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=18.0 (90), root[root]@localhost
  SELECT DISTINCT
  g2_AccessMap.g_accessListId
  FROM
  g2_AccessMap
  WHERE
  g2_AccessMap.g_userOrGroupId IN (N,N,N)
  AND
  g2_AccessMap.g_permission & N = N

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=17.0 (34), root[root]@localhost
  select id, tags from caches

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=17.0 (17), root[root]@localhost
  select id from caches

Count: 94  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=169.0 (15886), root[root]@localhost
  SELECT option_name, option_value FROM wp_options WHERE autoload = 'S'

Count: 9  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SELECT `comments`.*
  FROM (`comments`)
  WHERE `item_id` = N
  AND `state` = 'S'
  ORDER BY `created` ASC

Count: 8  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=15.0 (120), root[root]@localhost
  SELECT `tags`.*
  FROM (`tags`)
  ORDER BY `count` DESC
  LIMIT N, N

Count: 489  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  DELETE FROM `sessions` WHERE `last_activity` < N

Count: 10  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=23.0 (230), root[root]@localhost
  SELECT g_module, g_permission, g_description, g_bits, g_flags FROM g2_PermissionSetMap

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SELECT `items`.`id`
  FROM (`items`)
  LEFT JOIN `search_records` ON (`items`.`id` = `search_records`.`item_id`)
  WHERE (search_records.item_id IS NULL
  OR `search_records`.`dirty` = N)

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SELECT `items`.*
  FROM (`items`)
  WHERE `name` = 'S'
  AND `level` = N

Count: 5  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (5), root[root]@localhost
  SELECT `graphics_rules`.*
  FROM (`graphics_rules`)
  WHERE `target` = 'S'
  AND active = N
  ORDER BY `priority` ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=2.0 (2), root[root]@localhost
  select * from groups

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=5.0 (5), root[root]@localhost
  SELECT `logs`.*
  FROM (`logs`)
  ORDER BY `timestamp` DESC, `id` DESC
  LIMIT N, N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=210.0 (210), root[root]@localhost
  SELECT
  g2_TkOperatnMimeTypeMap.g_operationName,
  g2_TkOperatnMimeTypeMap.g_mimeType,
  g2_TkOperatnMimeTypeMap.g_toolkitId,
  g2_TkOperatnMimeTypeMap.g_priority
  FROM
  g2_TkOperatnMimeTypeMap
  WHERE
  g2_TkOperatnMimeTypeMap.g_priority >= N
  AND g2_TkOperatnMimeTypeMap.g_priority <= N

Count: 5  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=109.0 (545), root[root]@localhost
  SELECT DISTINCT
  g2_AccessMap.g_accessListId
  FROM
  g2_AccessMap
  WHERE
  g2_AccessMap.g_userOrGroupId IN (N,N,N,N)
  AND
  g2_AccessMap.g_permission & N = N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  SELECT
  COUNT(g2_Item.g_id)
  FROM
  g2_Item, g2_AccessSubscriberMap
  WHERE
  (g2_Item.g_description LIKE 'S' OR g2_Item.g_keywords LIKE 'S' OR g2_Item.g_summary LIKE 'S' OR g2_Item.g_title LIKE 'S')
  AND
  g2_Item.g_id = g2_AccessSubscriberMap.g_itemId
  AND
  g2_AccessSubscriberMap.g_accessListId IN (N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N)

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  DELETE FROM `caches` WHERE N

Count: 7  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=4.0 (28), root[root]@localhost
  SELECT `permissions`.*
  FROM (`permissions`)
  ORDER BY `permissions`.`id` ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=3.0 (3), root[root]@localhost
  select * from groups_users

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=3.0 (3), root[root]@localhost
  SELECT
  g2_Group.g_id,
  g2_Group.g_groupName
  FROM
  g2_Group
  ORDER BY
  g2_Group.g_groupName ASC
  LIMIT N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  SELECT
  g2_Item.g_id,
  g2_User.g_fullName,
  g2_User.g_userName,
  g2_Entity.g_modificationTimestamp, g2_Item.g_description, g2_Item.g_keywords, g2_Item.g_summary, g2_Item.g_title
  FROM
  g2_Item, g2_AccessSubscriberMap, g2_Entity, g2_User
  WHERE
  (g2_Item.g_description LIKE 'S' OR g2_Item.g_keywords LIKE 'S' OR g2_Item.g_summary LIKE 'S' OR g2_Item.g_title LIKE 'S')
  AND
  g2_Item.g_id = g2_AccessSubscriberMap.g_itemId
  AND
  g2_Item.g_id = g2_Entity.g_id
  AND
  g2_User.g_id = g2_Item.g_ownerId
  AND
  g2_AccessSubscriberMap.g_accessListId IN (N,N,N,N,N,N,N,N,N,N,N,N,N,N,N,N)
  ORDER BY
  g2_Entity.g_modificationTimestamp DESC, g2_Item.g_id DESC
  LIMIT N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=100.0 (100), root[root]@localhost
  SELECT g2_Item.g_id FROM g2_Entity, g2_Item WHERE g2_Entity.g_id = g2_Item.g_id AND g2_Entity.g_entityType IN ('S', 'S') AND g2_Item.g_id > N ORDER BY g2_Item.g_id ASC LIMIT N

Count: 16  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=11.1 (177), root[root]@localhost
  SELECT `modules`.*
  FROM (`modules`)
  ORDER BY `modules`.`id` ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  DELETE FROM search_records WHERE search_records.`item_id` NOT IN (SELECT `id` FROM items)

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  DELETE FROM exif_records WHERE exif_records.`item_id` NOT IN (SELECT `id` FROM items WHERE items.`type` = 'S')

Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SELECT `messages`.*
  FROM (`messages`)
  ORDER BY `messages`.`id` ASC

Count: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  UPDATE `graphics_rules` SET `active` = N WHERE `module_name` = 'S'

Count: 17  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=20.8 (353), root[root]@localhost
  SELECT `module_name`, `name`, `value`
  FROM (`vars`)
  ORDER BY `module_name` ASC

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=17.0 (17), root[root]@localhost
  select id, tags, expiration, length(cache) from caches


------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge  
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize  
details at: http://p.sf.net/sfu/Challenge
__[ g a l l e r y - d e v e l ]_________________________

[ list info/archive --> http://gallery.sf.net/lists.php ]
[ gallery info/FAQ/download --> http://gallery.sf.net ]

[Bharat Mediratta]

Stephen Lacy wrote:
> Attached are the slow query logs.  (Let me know if these don't come

Awesome, thanks for following through on this.

> through the mailing list properly).  The top offenders of total query
> time are:
>
> Count: 30167  Time=0.33s (10065s)  Lock=0.00s (2s)  Rows=0.0 (0),
> root[root]@loc
> alhost
>   UPDATE items SET `left` = `left` + N WHERE `left` >= N
>
> Count: 30167  Time=0.27s (7996s)  Lock=0.00s (3s)  Rows=0.0 (0),
> root[root]@loca
> lhost
>   UPDATE items SET `right` = `right` + N WHERE `right` >= N

These two are MPTT pointer maintenance updates.  We were worried that
this might lead to performance problems and had a discussion about this
a while back.  Looks like we're spending a total of about 600ms on
average there, but I suspect that's not the whole story.  If the update
time increases linearly with the size of the table, then it's at the
highest cost now and the cost will only increase.   Factors of interest
here:

1) Does analyzing the table affects its performance here?
2) Does reducing / removing indexes help?  Does it damage MPTT based
    queries?
3) Does InnoDB vs. MyISAM have an impact?

Here's at least one thread where we discussed it.
http://thread.gmane.org/gmane.comp.web.gallery.devel/5230/focus=5328

> Count: 31312  Time=0.07s (2347s)  Lock=0.00s (0s)  Rows=1.0 (31292),
> root[root]@
> localhost
>   SELECT *
>   FROM (`caches`)
>   WHERE `key` = 'S'
>
> Count: 31180  Time=0.06s (1915s)  Lock=0.02s (486s)  Rows=0.0 (0),
> root[root]@lo
> calhost
>   UPDATE `caches` SET `tags` = 'S', `expiration` = N, `cache` = 'S'
> WHERE `key`
> = 'S'

We should definitely not be doing 60k (71 minutes worth!) of cache
lookups and writes.  This bears investigation.

Ticket: http://sourceforge.net/apps/trac/gallery/ticket/575

> Count: 30167  Time=0.04s (1106s)  Lock=0.00s (1s)  Rows=1.0 (30167),
> root[root]@
> localhost
>   SELECT MAX(weight) as max_weight
>   FROM (`items`)
>   LIMIT N, N

Yeah this one sucks and can possibly be optimized.  When we assemble an
item we assign it a weight that we use for manual ordering.  It's
important that the weight be towards the end of the existing spectrum.
This code does not lock so there's no guarantee here that you're getting
the max value, but we expect that it'll be close enough to satisfy most
users.  We should probably switch this value to using the id instead
which would give us an increasing value.  It would result in gaps in the
weight, but that's something we can deal with.

Ticket: http://sourceforge.net/apps/trac/gallery/ticket/576

thanks, Steve!
-Bharat


------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge  
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize  
details at: http://p.sf.net/sfu/Challenge
__[ g a l l e r y - d e v e l ]_________________________

[ list info/archive --> http://gallery.sf.net/lists.php ]
[ gallery info/FAQ/download --> http://gallery.sf.net ]

[Steve Lacy]

If anyone is interested in the actual slow query logs (and not just the output of mysqldumpslow) then I'm happy to provide the logs.   Just e-mail me privately and I'll put them on a public dropzone.

They're about 1GB compressed, 24GB raw. :)   (They contain logs of every statement executed in this import)

Steve

On Mon, Jul 20, 2009 at 3:14 PM, Bharat Mediratta <bharat@...> wrote:

Stephen Lacy wrote:

Attached are the slow query logs.  (Let me know if these don't come

Awesome, thanks for following through on this.

through the mailing list properly).  The top offenders of total query time are:

Count: 30167  Time=0.33s (10065s)  Lock=0.00s (2s)  Rows=0.0 (0), root[root]@loc
alhost
 UPDATE items SET `left` = `left` + N WHERE `left` >= N

Count: 30167  Time=0.27s (7996s)  Lock=0.00s (3s)  Rows=0.0 (0), root[root]@loca
lhost
 UPDATE items SET `right` = `right` + N WHERE `right` >= N

These two are MPTT pointer maintenance updates.  We were worried that this might lead to performance problems and had a discussion about this a while back.  Looks like we're spending a total of about 600ms on average there, but I suspect that's not the whole story.  If the update time increases linearly with the size of the table, then it's at the highest cost now and the cost will only increase.   Factors of interest here:

1) Does analyzing the table affects its performance here?
2) Does reducing / removing indexes help?  Does it damage MPTT based
  queries?
3) Does InnoDB vs. MyISAM have an impact?

Here's at least one thread where we discussed it.
http://thread.gmane.org/gmane.comp.web.gallery.devel/5230/focus=5328

Count: 31312  Time=0.07s (2347s)  Lock=0.00s (0s)  Rows=1.0 (31292), root[root]@
localhost
 SELECT *
 FROM (`caches`)
 WHERE `key` = 'S'

Count: 31180  Time=0.06s (1915s)  Lock=0.02s (486s)  Rows=0.0 (0), root[root]@lo
calhost
 UPDATE `caches` SET `tags` = 'S', `expiration` = N, `cache` = 'S' WHERE `key`
= 'S'

We should definitely not be doing 60k (71 minutes worth!) of cache lookups and writes.  This bears investigation.

Ticket: http://sourceforge.net/apps/trac/gallery/ticket/575

Count: 30167  Time=0.04s (1106s)  Lock=0.00s (1s)  Rows=1.0 (30167), root[root]@
localhost
 SELECT MAX(weight) as max_weight
 FROM (`items`)
 LIMIT N, N

Yeah this one sucks and can possibly be optimized.  When we assemble an item we assign it a weight that we use for manual ordering.  It's important that the weight be towards the end of the existing spectrum. This code does not lock so there's no guarantee here that you're getting the max value, but we expect that it'll be close enough to satisfy most users.  We should probably switch this value to using the id instead which would give us an increasing value.  It would result in gaps in the weight, but that's something we can deal with.

Ticket: http://sourceforge.net/apps/trac/gallery/ticket/576

thanks, Steve!
-Bharat

------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge  
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize  
details at: http://p.sf.net/sfu/Challenge
__[ g a l l e r y - d e v e l ]_________________________

[ list info/archive --> http://gallery.sf.net/lists.php ]
[ gallery info/FAQ/download --> http://gallery.sf.net ]

[Bharat Mediratta]

Bharat Mediratta wrote:

>> Count: 31312  Time=0.07s (2347s)  Lock=0.00s (0s)  Rows=1.0 (31292),
>> root[root]@
>> localhost
>>   SELECT *
>>   FROM (`caches`)
>>   WHERE `key` = 'S'
>>
>> Count: 31180  Time=0.06s (1915s)  Lock=0.02s (486s)  Rows=0.0 (0),
>> root[root]@lo
>> calhost
>>   UPDATE `caches` SET `tags` = 'S', `expiration` = N, `cache` = 'S'
>> WHERE `key`
>> = 'S'
>
> We should definitely not be doing 60k (71 minutes worth!) of cache
> lookups and writes.  This bears investigation.
>
> Ticket: http://sourceforge.net/apps/trac/gallery/ticket/575

This is because of all the informational logging we were doing during
the import process.  I fixed this a few days ago and have closed the ticket.

-Bharat

------------------------------------------------------------------------------
Enter the BlackBerry Developer Challenge  
This is your chance to win up to $100,000 in prizes! For a limited time,
vendors submitting new applications to BlackBerry App World(TM) will have
the opportunity to enter the BlackBerry Developer Challenge. See full prize  
details at: http://p.sf.net/sfu/Challenge
__[ g a l l e r y - d e v e l ]_________________________

[ list info/archive --> http://gallery.sf.net/lists.php ]
[ gallery info/FAQ/download --> http://gallery.sf.net ]