Description

Another binary logs of death follow-up.:

[09:11am] ben-agaric: we've got a test site (it does have custom modules/code) that's putting about a gigabyte into its binary mysql logs every couple days
[09:11am] ben-agaric: all I see when I look into it is cache insert after cache insert. Any idea what would do that?
[09:12am] jredding: ben-agaric: Are you talking about your mysql logs? or the Drupal logs?
[09:12am] ben-agaric: mysql logs for a Drupal site
[09:12am] jredding: and in mysql are you Query logging?
[09:12am] jredding: i.e. can you see Queries in your logs?
[09:13am] ben-agaric: only inserts etc, not selects
[09:13am] jredding: aah.. that's still a big performance hit.. to be logging all queries even if not selects.. but still..
[09:13am] jredding: insert have to happen to get data into the cache..
[09:14am] jredding: you have to track down if its excessive..
[09:14am] jredding: check your cache settings..
[09:14am] jredding: for lifetime..
[09:14am] ben-agaric: just turned on caching
[09:14am] ben-agaric: it's the core caches that you can't turn off that's somehow been generating all this
[09:14am] ben-agaric: http://agaricdesign.com/note/mysql-binary-logs-death

[09:16am] ben-agaric: to log to /var/log/mysql seems to be a standard setting on Debian/Apache... but the logs on our production server, which has a dozen sites, makes a new mysq-bin.000123 file every several days or so, and I don't run into cache table inserts
[09:17am] ben-agaric: so somehow, somewhere, I think we must be making it redo the cache all the time. Unless it's just the process of development combined with i18n
[09:18am] jredding: ben-agaric: So are you worried about the mysql logging issue or that Drupal is doing too many inserts?
[09:19am] ben-agaric: yeah, I'm afraid the mysql log activity is a symptom of a worse cause
[09:19am] ben-agaric: i know we could turn logging off.
[09:21am] jredding: i18n is a heavy module.. have you checked what happens when you turn that off...
[09:21am] jredding: I mean it seems that you're bigger issue if with too many queries.. and if its core that caching too much and lifetime is helping.
[09:21am] jredding: then I'd just dig and find out why exactly its being so excessive..
[09:29am] ben-agaric: it seems it's entirely the menu cache
[09:29am] ben-agaric: so something is causing that to need to be recached constantly

I think I'm almost there. It's got to be menu_rebuild that's getting called too often.

If I run a debug backtrace on menu_rebuild (looking at Arto's trace module rather than rolling my own again) this really should identify it.

UPDATE: Going through the trace logs did turn up not menu_rebuild, but calls to _menu_build() over and over again.

It's triggered from the View module, but only for GMap Views. In the logs there will be several sequences like the one attached that have a call to _menu_build() and then another giant insert into the menu caching table {}menu_cache}.

Here's the function:
http://api.drupal.org/api/function/_menu_build/5

It's querying the whole database so it must be an unnecessary hit even if it's not causing the menu cache rebuilding, and I don't think views has any business calling it directly for any reason. And I don't see it being called for non-GMap views.

Anyhow, attached are excerpts from the debug logging by trace.module.