[Zope] ZSQL Method Timings/Profiling or MySQL SQL Execution Timing Statistics

[knight]

  This message is in MIME format.  The first part should be readable text,
  while the remaining parts are likely unreadable without MIME-aware tools.
  Send mail to mime@docserver.cac.washington.edu for more info.

--0-410579625-971140523=:13589
Content-Type: TEXT/PLAIN; charset=US-ASCII

I'm answering myself because I found a solution to my problem, and I
wanted to share the results with the list, in case someone is struggling
to try to do the same thing...

The problem with mysql (go easy, we're not talking about the fact that
mysql is primitive and overall does not match up to the known
transactional rdbms) is that it does not provide any sql statement
profiling or timing statistics. If you use the mysql client to check a
query, you can see a time. You can even write a perl script utilizing the
benchmark module that comes with mysql to get more sql timings.

However, neither of these methods work with Zope (i.e. do you really feel
like interfacing to perl from Zope, and then calling the benchmark module
for EVERY one of your queries?). A more "automated" approach is desirable,
that compares to Oracle's profiling that logs ALL queries to a file with
timing statistics.

I finally decided after searching for a few hours for information, that I
would modify Zope to handle this for me. The logical place was to put it
in ZMySQLDA. I'm attaching a patch of a really _simple_ logging
mechanism. The only activity that really occurs is the time is noted
before and after the query gets processed and fetched, and the difference
is noted. Finally, it gets logged to /tmp/mysql_timing.log --- You need to
turn off MYSQL_TIMING in db.py of ZMySQL after applying the patch should
you not want the timing to occur any longer. And as usual, a Zope restart
is required after patching your ZMySQLDA.

The patch was written for ZMySQLDA 1.2.0 (nothing below).

Knight
knight@phunc.com

On Mon, 9 Oct 2000, knight wrote:

> Greetings,
> 
> I have a lot of past experience with tuning and timing on Oracle (quite
> simple), but I seem to have hit a hurdle with timing my sql statements in
> MySQL. Getting these timings are _incredibly_ important to finding
> bottlenecks in a web site's performance...
> 
> Now, first, is it possible to turn on profiling for ZSQL methods? I've
> turned on my Zope's profiling, and I can see statistics on how many times
> sqlvar was called, but not specific zsql methods. Second, anyone familiar
> with any mysql settings that will dump a log displaying real-time sql
> executions and the corresponding execute time?
> 
> I like to turn sql timing on, then run around the site for a while, send
> some people to test it out, or throw up a http load tester script up, and
> then check the timing logs to see how things worked out.
> 
> Regards,
> 
> Knight
> knight@phunc.com
> 
> 
> _______________________________________________
> Zope maillist  -  Zope@zope.org
> http://lists.zope.org/mailman/listinfo/zope
> **   No cross posts or HTML encoding!  **
> (Related lists - 
>  http://lists.zope.org/mailman/listinfo/zope-announce
>  http://lists.zope.org/mailman/listinfo/zope-dev )
> 
> 

--0-410579625-971140523=:13589
Content-Type: TEXT/PLAIN; charset=US-ASCII; name="mysqlda_timing.patch"
Content-Transfer-Encoding: BASE64
Content-ID: <Pine.BSF.4.21.0010091815230.13589@totally.righteous.net>
Content-Description: 
Content-Disposition: attachment; filename="mysqlda_timing.patch"

LS0tIGRiLnB5CVRodSBKdW4gMTUgMDI6MTA6NDEgMjAwMA0KKysrIGRiLnB5
CU1vbiBPY3QgIDkgMTg6MDY6NTMgMjAwMA0KQEAgLTE0Miw2ICsxNDIsMTIg
QEANCiANCiAgICAgZGVmIF9faW5pdF9fKHNlbGYsY29ubmVjdGlvbik6DQog
ICAgICAgICBzZWxmLmNvbm5lY3Rpb249Y29ubmVjdGlvbg0KKyAgICAgICAg
c2VsZi5NWVNRTF9USU1JTkcgPSAxDQorICAgICAgICBpZiBzZWxmLk1ZU1FM
X1RJTUlORzoNCisgICAgICAgICAgc2VsZi50aW1pbmdsb2cgPSBvcGVuKCcv
dG1wL215c3FsX3RpbWluZy5sb2cnLCAndysnKQ0KKyAgICAgICAgICBpZiBu
b3Qgc2VsZi50aW1pbmdsb2c6DQorICAgICAgICAgICAgcHJpbnQgIkVycm9y
OiBDYW4ndCBvcGVuIC90bXAvbXlzcWxfdGltaW5nLmxvZyBmb3Igd3JpdGlu
ZyINCisgICAgICAgICAgICBzZWxmLk1ZU1FMX1RJTUlORyA9IE5vbmUNCiAN
CiAgICAgICAgIGluZm89c3BsaXQoY29ubmVjdGlvbikNCiAgICAgICAgIGlm
IGluZm8gYW5kIGxlbihpbmZvKSA8IDQ6DQpAQCAtMTc0LDYgKzE4MCw3IEBA
DQogICAgICAgICAgICAgICBzZWxlY3RfbT1yZWdleC5jb21waWxlKCdbXDAt
IF0qc2VsZWN0W1wwLSBdKycsDQogICAgICAgICAgICAgICAgICAgICAgICAg
ICAgICAgICAgICAgIHJlZ2V4LmNhc2Vmb2xkKS5tYXRjaCwNCiAgICAgICAg
ICAgICAgICk6DQorICAgICAgICBpbXBvcnQgdGltZQ0KICAgICAgICAgZGI9
c2VsZi5kYg0KICAgICAgICAgdHJ5Og0KICAgICAgICAgICAgIHF1ZXJpZXM9
ZmlsdGVyKE5vbmUsIG1hcChzdHJpcCxzcGxpdChxdWVyeV9zdHJpbmcsICdc
MCcpKSkNCkBAIC0xODEsMTEgKzE4OCwyMiBAQA0KICAgICAgICAgICAgIHJl
c3VsdD0oKQ0KICAgICAgICAgICAgIGRlc2M9Tm9uZQ0KICAgICAgICAgICAg
IGZvciBxcyBpbiBxdWVyaWVzOg0KKyAgICAgICAgICAgICAgICBpZiBzZWxm
Lk1ZU1FMX1RJTUlORzoNCisgICAgICAgICAgICAgICAgICBzdGFydF90aW1l
ID0gdGltZS50aW1lKCkNCiAgICAgICAgICAgICAgICAgZGIucXVlcnkocXMp
DQorDQogICAgICAgICAgICAgICAgIGM9ZGIuc3RvcmVfcmVzdWx0KCkNCiAg
ICAgICAgICAgICAgICAgdHJ5Og0KICAgICAgICAgICAgICAgICAgICAgZGVz
Yz1jLmRlc2NyaWJlKCkNCiAgICAgICAgICAgICAgICAgICAgIHI9Yy5mZXRj
aF9hbGxfcm93cygpDQorICAgICAgICAgICAgICAgICAgICBpZiBzZWxmLk1Z
U1FMX1RJTUlORzoNCisgICAgICAgICAgICAgICAgICAgICAgZW5kX3RpbWUg
PSB0aW1lLnRpbWUoKQ0KKyAgICAgICAgICAgICAgICAgICAgICB0b3RfdGlt
ZSA9IGVuZF90aW1lIC0gc3RhcnRfdGltZQ0KKyAgICAgICAgICAgICAgICAg
ICAgICB0bXBzdHIgPSAiU1FMIFN0YXRlbWVudDogIiArIHFzICsgIlxuIg0K
KyAgICAgICAgICAgICAgICAgICAgICBzZWxmLnRpbWluZ2xvZy53cml0ZSh0
bXBzdHIpDQorICAgICAgICAgICAgICAgICAgICAgIHRtcHN0ciA9ICJFeGVj
dXRpb24gVGltZTogIiArIHN0cih0b3RfdGltZSoxMDAwKSArICIgbWlsaXNl
Y29uZHMgKG1zKVxuXG4iDQorICAgICAgICAgICAgICAgICAgICAgIHNlbGYu
dGltaW5nbG9nLndyaXRlKHRtcHN0cikNCisgICAgICAgICAgICAgICAgICAg
ICAgc2VsZi50aW1pbmdsb2cuZmx1c2goKQ0KICAgICAgICAgICAgICAgICBl
eGNlcHQ6IHI9Tm9uZQ0KICAgICAgICAgICAgICAgICBpZiBub3QgcjogY29u
dGludWUNCiAgICAgICAgICAgICAgICAgaWYgcmVzdWx0Og0K
--0-410579625-971140523=:13589--