[Davical-general] Possible slow query: SQ

classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

[Davical-general] Possible slow query: SQ

phil
I’m running davical on my raspberry pi since a long time and it did the
job pretty well.  However I did encounter some issue while testing the
upgrade from Raspbian Wheezy (davical 1.1.1-1, postgresql-9.1) to Jessie
(davical 1.1.3.1-1, postgresql-9.4), the following errors appears in
apache logs:

========================================================================================================
[Sun Jun 12 17:18:53.971014 2016] [:error] [pid 842] [client
192.168.1.120:38130] davical: LOG: REPORT: Query: Possible slow query:
SQ in '/usr/share/davical/inc/caldav-REPORT-sync-collection.php' on line
124
[Sun Jun 12 17:18:53.974902 2016] [:error] [pid 842] [client
192.168.1.120:38130] davical: LOG: REPORT: Query: SQ: Took: 0.381095 for
SELECT collection.*, calendar_item.*, caldav_data.*,
addressbook_resource.*, 201 AS sync_status FROM collection LEFT JOIN
caldav_data USING (collection_id) LEFT JOIN calendar_item USING (dav_id)
LEFT JOIN addressbook_reso
[Sun Jun 12 17:18:53.975332 2016] [:error] [pid 842] [client
192.168.1.120:38130] davical: LOG: REPORT: Query: SQ: urce USING
(dav_id) WHERE collection.collection_id = :collection_id ORDER BY
collection.collection_id, caldav_data.dav_id
[Sun Jun 12 17:30:24.359934 2016] [:error] [pid 642] [client
192.168.1.120:40651] davical: LOG: REPORT: Query: Possible slow query:
SQ in '/usr/share/davical/inc/caldav-REPORT-sync-collection.php' on line
124
[Sun Jun 12 17:30:24.365467 2016] [:error] [pid 642] [client
192.168.1.120:40651] davical: LOG: REPORT: Query: SQ: Took: 0.373486 for
SELECT collection.*, calendar_item.*, caldav_data.*,
addressbook_resource.*, 201 AS sync_status FROM collection LEFT JOIN
caldav_data USING (collection_id) LEFT JOIN calendar_item USING (dav_id)
LEFT JOIN addressbook_reso
[Sun Jun 12 17:30:24.366542 2016] [:error] [pid 642] [client
192.168.1.120:40651] davical: LOG: REPORT: Query: SQ: urce USING
(dav_id) WHERE collection.collection_id = :collection_id ORDER BY
collection.collection_id, caldav_data.dav_id
[Sun Jun 12 17:32:10.550431 2016] [:error] [pid 834] [client
192.168.1.120:36520] davical: LOG: REPORT: Query: Possible slow query:
SQ in '/usr/share/davical/inc/caldav-REPORT-sync-collection.php' on line
124
[Sun Jun 12 17:32:10.555844 2016] [:error] [pid 834] [client
192.168.1.120:36520] davical: LOG: REPORT: Query: SQ: Took: 0.433395 for
SELECT collection.*, calendar_item.*, caldav_data.*,
addressbook_resource.*, 201 AS sync_status FROM collection LEFT JOIN
caldav_data USING (collection_id) LEFT JOIN calendar_item USING (dav_id)
LEFT JOIN addressbook_reso
[Sun Jun 12 17:32:10.556934 2016] [:error] [pid 834] [client
192.168.1.120:36520] davical: LOG: REPORT: Query: SQ: urce USING
(dav_id) WHERE collection.collection_id = :collection_id ORDER BY
collection.collection_id, caldav_data.dav_id
[Sun Jun 12 17:32:49.439883 2016] [:error] [pid 871] [client
192.168.1.120:36917] davical: LOG: REPORT: Query: Possible slow query:
SQ in '/usr/share/davical/inc/caldav-REPORT-sync-collection.php' on line
124
[Sun Jun 12 17:32:49.445432 2016] [:error] [pid 871] [client
192.168.1.120:36917] davical: LOG: REPORT: Query: SQ: Took: 0.369395 for
SELECT collection.*, calendar_item.*, caldav_data.*,
addressbook_resource.*, 201 AS sync_status FROM collection LEFT JOIN
caldav_data USING (collection_id) LEFT JOIN calendar_item USING (dav_id)
LEFT JOIN addressbook_reso
[Sun Jun 12 17:32:49.446323 2016] [:error] [pid 871] [client
192.168.1.120:36917] davical: LOG: REPORT: Query: SQ: urce USING
(dav_id) WHERE collection.collection_id = :collection_id ORDER BY
collection.collection_id, caldav_data.dav_id
[Sun Jun 12 17:33:16.704542 2016] [:error] [pid 642] [client
192.168.1.120:43469] davical: LOG: REPORT: Query: Possible slow query:
SQ in '/usr/share/davical/inc/caldav-REPORT-sync-collection.php' on line
124
[Sun Jun 12 17:33:16.710133 2016] [:error] [pid 642] [client
192.168.1.120:43469] davical: LOG: REPORT: Query: SQ: Took: 0.372811 for
SELECT collection.*, calendar_item.*, caldav_data.*,
addressbook_resource.*, 201 AS sync_status FROM collection LEFT JOIN
caldav_data USING (collection_id) LEFT JOIN calendar_item USING (dav_id)
LEFT JOIN addressbook_reso
[Sun Jun 12 17:33:16.710994 2016] [:error] [pid 642] [client
192.168.1.120:43469] davical: LOG: REPORT: Query: SQ: urce USING
(dav_id) WHERE collection.collection_id = :collection_id ORDER BY
collection.collection_id, caldav_data.dav_id
[Sun Jun 12 18:03:43.207154 2016] [:error] [pid 871] [client
192.168.1.44:33367] davical: LOG: Session: Query: SQ: Took: 0.368973 for
UPDATE session SET session_end = current_timestamp WHERE session_id=?,
referer: http://cal.turtle.internal/tools.php
[Sun Jun 12 18:03:43.318960 2016] [:error] [pid 871] [client
192.168.1.44:33367] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'dav_principal' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/tools.php
[Sun Jun 12 18:04:05.667948 2016] [:error] [pid 641] [client
192.168.1.44:33453] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'dav_principal' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal
[Sun Jun 12 18:04:05.983313 2016] [:error] [pid 641] [client
192.168.1.44:33453] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname = 'grants'
AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal
[Sun Jun 12 18:04:06.021145 2016] [:error] [pid 641] [client
192.168.1.44:33453] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'access_ticket' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal
[Sun Jun 12 18:04:18.657513 2016] [:error] [pid 834] [client
192.168.1.44:33497] davical: LOG: Session: Query: SQ: Took: 0.391953 for
UPDATE usr SET last_used = (SELECT session_start FROM session WHERE
session.user_no = ? ORDER BY session_id DESC LIMIT 1) WHERE user_no =
?;, referer: http://cal.turtle.internal/index.php?logout
[Sun Jun 12 18:04:48.706542 2016] [:error] [pid 644] [client
192.168.1.44:33598] davical: LOG: Session: Query: SQ: Took: 0.395772 for
UPDATE usr SET last_used = (SELECT session_start FROM session WHERE
session.user_no = ? ORDER BY session_id DESC LIMIT 1) WHERE user_no =
?;, referer: http://cal.turtle.internal/index.php?logout
[Sun Jun 12 18:14:54.204899 2016] [:error] [pid 642] [client
192.168.1.44:35665] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'dav_principal' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=browse&t=principal&type=1
[Sun Jun 12 18:14:54.265269 2016] [:error] [pid 641] [client
192.168.1.44:35680] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'dav_principal' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=browse&t=principal&type=1
[Sun Jun 12 18:14:54.460992 2016] [:error] [pid 642] [client
192.168.1.44:35665] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname = 'grants'
AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=browse&t=principal&type=1
[Sun Jun 12 18:14:54.491771 2016] [:error] [pid 641] [client
192.168.1.44:35680] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname = 'grants'
AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=browse&t=principal&type=1
[Sun Jun 12 18:14:54.534994 2016] [:error] [pid 642] [client
192.168.1.44:35665] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'access_ticket' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=browse&t=principal&type=1
[Sun Jun 12 18:14:54.585075 2016] [:error] [pid 641] [client
192.168.1.44:35680] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'access_ticket' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=browse&t=principal&type=1
[Sun Jun 12 18:14:58.252584 2016] [:error] [pid 641] [client
192.168.1.44:35680] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'dav_principal' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal&id=1001
[Sun Jun 12 18:14:58.369855 2016] [:error] [pid 641] [client
192.168.1.44:35680] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname = 'grants'
AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal&id=1001
[Sun Jun 12 18:14:58.412722 2016] [:error] [pid 641] [client
192.168.1.44:35680] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'access_ticket' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal&id=1001
[Sun Jun 12 18:15:09.098569 2016] [:error] [pid 834] [client
192.168.1.44:35737] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'dav_principal' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal&subaction=delete_principal&id=1001
[Sun Jun 12 18:15:09.218946 2016] [:error] [pid 834] [client
192.168.1.44:35737] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname = 'grants'
AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal&subaction=delete_principal&id=1001
[Sun Jun 12 18:15:09.261595 2016] [:error] [pid 834] [client
192.168.1.44:35737] SELECT f.attname AS fieldname, t.typname AS
typename, f.atttypmod AS precision FROM pg_attribute f JOIN pg_class c
ON ( f.attrelid = c.oid ) JOIN pg_type t ON ( f.atttypid = t.oid ) JOIN
pg_namespace ns ON ( c.relnamespace = ns.oid ) WHERE relname =
'access_ticket' AND attnum >= 0  ORDER BY f.attnum, referer:
http://cal.turtle.internal/admin.php?action=edit&t=principal&subaction=delete_principal&id=1001
[Sun Jun 12 18:16:12.915382 2016] [:error] [pid 643] [client
192.168.1.44:35951] davical: LOG: Session: Query: SQ: Took: 0.663855 for
UPDATE session SET session_end = current_timestamp WHERE session_id=?,
referer: http://cal.turtle.internal/tools.php
========================================================================================================

I did a fresh install and did simply follow the backup/restore procedure
(trough postgresql dump) as described in the wiki. Then I  run the
update-davical-database script.  I have made many tests, I did even
tried on Netbsd7 (which run nicely on pi btw), installing 1.1.4 by hand,
but the same error appears in apache logs.

However, I can’t reproduce the problem on a AMD64 VM, with the same
davical database.  So I’m wondering about the root cause of the problem.

Is it a Arm or performance issue or is there something wrong in my db,
again it works nicely on wheezy.

Any help would be much appreciated ☺

Philippe

------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are
consuming the most bandwidth. Provides multi-vendor support for NetFlow,
J-Flow, sFlow and other flows. Make informed decisions using capacity planning
reports. http://sdm.link/zohomanageengine
_______________________________________________
Davical-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/davical-general
Reply | Threaded
Open this post in threaded view
|

Re: Possible slow query: SQ

Florian Schlichting-2
Hi Philippe,

> I???m running davical on my raspberry pi since a long time and it did the
> job pretty well.  However I did encounter some issue while testing the
> upgrade from Raspbian Wheezy (davical 1.1.1-1, postgresql-9.1) to Jessie
> (davical 1.1.3.1-1, postgresql-9.4), the following errors appears in
> apache logs:

those aren't really errors, just a combination of overly verbose logging
of admin UI accesses (fixed in 1.1.4, in jessie-backports) and slow
query notices - those are probably related to the limited hardware
resources of a raspberry pi, but then the displayed times are still very
much ok and the default threshold for those notices was just raised from
0.3 to 5 seconds in git.

So don't worry, but do update to the current version as it contains many
bug fixes!

Florian


------------------------------------------------------------------------------
What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
patterns at an interface-level. Reveals which users, apps, and protocols are
consuming the most bandwidth. Provides multi-vendor support for NetFlow,
J-Flow, sFlow and other flows. Make informed decisions using capacity planning
reports.http://sdm.link/zohodev2dev
_______________________________________________
Davical-general mailing list
[hidden email]
https://lists.sourceforge.net/lists/listinfo/davical-general