View Issue Details

IDProjectCategoryView StatusLast Update
0013732Tine 2.0CardDAVpublic2018-03-15 14:42
Reporternbe-renzel-netAssigned Topschuele 
PrioritynormalSeverityblockReproducibilityalways
Status feedbackResolutionopen 
Product Version2017.08.11 Community Edition 
Target VersionFixed in Version 
Summary0013732: After upgrade to 2017.08.11, syncing our mobile devices using CardDAV is killing PostgreSQL using 100% CPU for a query...
DescriptionAfter upgrading to 2017.08.11, during CardDAV sync (via DAVdroid), the following query takes extremely long and is killing PostgreSQL using 100% CPU per sync session.

This is the query:
------------------------------------------------------------------------------------------------------------------------------------------------
LOG: duration: 2794.698 ms execute pdo_stmt_000039a1: SELECT "addressbook_lists"."id", MIN("addressbook_lists"."container_id") AS "container_id", MIN("addressbook_lists"."name") AS "name", MIN("addressbook_lists"."description") AS "description", MIN("addressbook_lists"."email") AS "email", MIN("addressbook_lists"."type") AS "type", MIN("addressbook_lists"."list_type") AS "list_type", MIN("addressbook_lists"."created_by") AS "created_by", MIN("addressbook_lists"."creation_time") AS "creation_time", MIN("addressbook_lists"."last_modified_by") AS "last_modified_by", MIN("addressbook_lists"."last_modified_time") AS "last_modified_time", MIN("addressbook_lists"."is_deleted") AS "is_deleted", MIN("addressbook_lists"."deleted_by") AS "deleted_by", MIN("addressbook_lists"."deleted_time") AS "deleted_time", MIN("addressbook_lists"."seq") AS "seq", MIN((SELECT array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("email"))),',') FROM "tine20_addressbook" WHERE ("id" IN (SELECT "addressbook_list_members"."contact_id" FROM "tine20_addressbook_list_members" AS "addressbook_list_members" WHERE ("addressbook_list_members"."list_id" = "addressbook_lists"."id"))))) AS "emails", array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("addressbook_list_members"."contact_id"))),',') AS "members", MIN("groups"."id") AS "group_id" FROM "tine20_addressbook_lists" AS "addressbook_lists"
         LEFT JOIN "tine20_addressbook_list_members" AS "addressbook_list_members" ON "addressbook_lists"."id" = "addressbook_list_members"."list_id"
         LEFT JOIN "tine20_groups" AS "groups" ON "addressbook_lists"."id" = "groups"."list_id" WHERE ("addressbook_lists"."is_deleted" = 0) AND ("addressbook_lists"."id" IN ('919b9a87ad3e47925eaf9227cdeae39931e5bdf3', 'c308b2fc7fcdf66fda1d10cca31fc15029fc4d0d', '73b7ec1e2200bded7d3e656fa7f1620c7e6b11b8', 'b359363d39912398e2cca2aed96f5be51b3d3305', '95d950362c16e07c5626cdf2a35453b8527a1528', '27a643c2bcda02c8e3bd05c93aec77e0d2c80eba')) AND ("addressbook_lists"."container_id" IN ('1') /* add acl in getMultiple */) GROUP BY "addressbook_lists"."id"
LOG: duration: 2900.978 ms execute pdo_stmt_000039ac: SELECT "addressbook_lists"."id", MIN("addressbook_lists"."container_id") AS "container_id", MIN("addressbook_lists"."name") AS "name", MIN("addressbook_lists"."description") AS "description", MIN("addressbook_lists"."email") AS "email", MIN("addressbook_lists"."type") AS "type", MIN("addressbook_lists"."list_type") AS "list_type", MIN("addressbook_lists"."created_by") AS "created_by", MIN("addressbook_lists"."creation_time") AS "creation_time", MIN("addressbook_lists"."last_modified_by") AS "last_modified_by", MIN("addressbook_lists"."last_modified_time") AS "last_modified_time", MIN("addressbook_lists"."is_deleted") AS "is_deleted", MIN("addressbook_lists"."deleted_by") AS "deleted_by", MIN("addressbook_lists"."deleted_time") AS "deleted_time", MIN("addressbook_lists"."seq") AS "seq", MIN((SELECT array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("email"))),',') FROM "tine20_addressbook" WHERE ("id" IN (SELECT "addressbook_list_members"."contact_id" FROM "tine20_addressbook_list_members" AS "addressbook_list_members" WHERE ("addressbook_list_members"."list_id" = "addressbook_lists"."id"))))) AS "emails", array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("addressbook_list_members"."contact_id"))),',') AS "members", MIN("groups"."id") AS "group_id" FROM "tine20_addressbook_lists" AS "addressbook_lists"
         LEFT JOIN "tine20_addressbook_list_members" AS "addressbook_list_members" ON "addressbook_lists"."id" = "addressbook_list_members"."list_id"
         LEFT JOIN "tine20_groups" AS "groups" ON "addressbook_lists"."id" = "groups"."list_id" WHERE ("addressbook_lists"."is_deleted" = 0) AND ("addressbook_lists"."id" IN ('919b9a87ad3e47925eaf9227cdeae39931e5bdf3', 'c308b2fc7fcdf66fda1d10cca31fc15029fc4d0d', '73b7ec1e2200bded7d3e656fa7f1620c7e6b11b8', 'b359363d39912398e2cca2aed96f5be51b3d3305', '95d950362c16e07c5626cdf2a35453b8527a1528', '27a643c2bcda02c8e3bd05c93aec77e0d2c80eba')) AND ("addressbook_lists"."container_id" IN ('1') /* add acl in getMultiple */) GROUP BY "addressbook_lists"."id"
LOG: duration: 2846.553 ms execute pdo_stmt_000039cb: SELECT "addressbook_lists"."id", MIN("addressbook_lists"."container_id") AS "container_id", MIN("addressbook_lists"."name") AS "name", MIN("addressbook_lists"."description") AS "description", MIN("addressbook_lists"."email") AS "email", MIN("addressbook_lists"."type") AS "type", MIN("addressbook_lists"."list_type") AS "list_type", MIN("addressbook_lists"."created_by") AS "created_by", MIN("addressbook_lists"."creation_time") AS "creation_time", MIN("addressbook_lists"."last_modified_by") AS "last_modified_by", MIN("addressbook_lists"."last_modified_time") AS "last_modified_time", MIN("addressbook_lists"."is_deleted") AS "is_deleted", MIN("addressbook_lists"."deleted_by") AS "deleted_by", MIN("addressbook_lists"."deleted_time") AS "deleted_time", MIN("addressbook_lists"."seq") AS "seq", MIN((SELECT array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("email"))),',') FROM "tine20_addressbook" WHERE ("id" IN (SELECT "addressbook_list_members"."contact_id" FROM "tine20_addressbook_list_members" AS "addressbook_list_members" WHERE ("addressbook_list_members"."list_id" = "addressbook_lists"."id"))))) AS "emails", array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("addressbook_list_members"."contact_id"))),',') AS "members", MIN("groups"."id") AS "group_id" FROM "tine20_addressbook_lists" AS "addressbook_lists"
         LEFT JOIN "tine20_addressbook_list_members" AS "addressbook_list_members" ON "addressbook_lists"."id" = "addressbook_list_members"."list_id"
         LEFT JOIN "tine20_groups" AS "groups" ON "addressbook_lists"."id" = "groups"."list_id" WHERE ("addressbook_lists"."is_deleted" = 0) AND ("addressbook_lists"."id" IN ('919b9a87ad3e47925eaf9227cdeae39931e5bdf3', 'c308b2fc7fcdf66fda1d10cca31fc15029fc4d0d', '73b7ec1e2200bded7d3e656fa7f1620c7e6b11b8', 'b359363d39912398e2cca2aed96f5be51b3d3305', '95d950362c16e07c5626cdf2a35453b8527a1528', '27a643c2bcda02c8e3bd05c93aec77e0d2c80eba')) AND ("addressbook_lists"."container_id" IN ('1') /* add acl in getMultiple */) GROUP BY "addressbook_lists"."id"
LOG: duration: 2851.564 ms execute pdo_stmt_000039dc: SELECT "addressbook_lists"."id", MIN("addressbook_lists"."container_id") AS "container_id", MIN("addressbook_lists"."name") AS "name", MIN("addressbook_lists"."description") AS "description", MIN("addressbook_lists"."email") AS "email", MIN("addressbook_lists"."type") AS "type", MIN("addressbook_lists"."list_type") AS "list_type", MIN("addressbook_lists"."created_by") AS "created_by", MIN("addressbook_lists"."creation_time") AS "creation_time", MIN("addressbook_lists"."last_modified_by") AS "last_modified_by", MIN("addressbook_lists"."last_modified_time") AS "last_modified_time", MIN("addressbook_lists"."is_deleted") AS "is_deleted", MIN("addressbook_lists"."deleted_by") AS "deleted_by", MIN("addressbook_lists"."deleted_time") AS "deleted_time", MIN("addressbook_lists"."seq") AS "seq", MIN((SELECT array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("email"))),',') FROM "tine20_addressbook" WHERE ("id" IN (SELECT "addressbook_list_members"."contact_id" FROM "tine20_addressbook_list_members" AS "addressbook_list_members" WHERE ("addressbook_list_members"."list_id" = "addressbook_lists"."id"))))) AS "emails", array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("addressbook_list_members"."contact_id"))),',') AS "members", MIN("groups"."id") AS "group_id" FROM "tine20_addressbook_lists" AS "addressbook_lists"
         LEFT JOIN "tine20_addressbook_list_members" AS "addressbook_list_members" ON "addressbook_lists"."id" = "addressbook_list_members"."list_id"
         LEFT JOIN "tine20_groups" AS "groups" ON "addressbook_lists"."id" = "groups"."list_id" WHERE ("addressbook_lists"."is_deleted" = 0) AND ("addressbook_lists"."id" IN ('754dbb3408a4a335c5539ad176b987291f6b2cf3', 'b359363d39912398e2cca2aed96f5be51b3d3305', '549f3500378bc5678e1efd734de6dd08a9638187', 'd2a05652954c6768cecfea4679e293a42b0e7bbc', 'fef6534562e28e90997202c2a443b4af8a82f3a9', '19dbcedf67391d1ea020a6cf9454ca0e89bf0aed', '6742543a2b1f3f817042b5573098c422213ca634', '77b21379dc9e4202b89d4c8f5b8210fd940401cf', 'c308b2fc7fcdf66fda1d10cca31fc15029fc4d0d', '27a643c2bcda02c8e3bd05c93aec77e0d2c80eba', '61d0625b58a7c74ee176d7a009c21138428084fc')) AND ("addressbook_lists"."container_id" IN ('1') /* add acl in getMultiple */) GROUP BY "addressbook_lists"."id"
LOG: duration: 2858.494 ms execute pdo_stmt_000039e7: SELECT "addressbook_lists"."id", MIN("addressbook_lists"."container_id") AS "container_id", MIN("addressbook_lists"."name") AS "name", MIN("addressbook_lists"."description") AS "description", MIN("addressbook_lists"."email") AS "email", MIN("addressbook_lists"."type") AS "type", MIN("addressbook_lists"."list_type") AS "list_type", MIN("addressbook_lists"."created_by") AS "created_by", MIN("addressbook_lists"."creation_time") AS "creation_time", MIN("addressbook_lists"."last_modified_by") AS "last_modified_by", MIN("addressbook_lists"."last_modified_time") AS "last_modified_time", MIN("addressbook_lists"."is_deleted") AS "is_deleted", MIN("addressbook_lists"."deleted_by") AS "deleted_by", MIN("addressbook_lists"."deleted_time") AS "deleted_time", MIN("addressbook_lists"."seq") AS "seq", MIN((SELECT array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("email"))),',') FROM "tine20_addressbook" WHERE ("id" IN (SELECT "addressbook_list_members"."contact_id" FROM "tine20_addressbook_list_members" AS "addressbook_list_members" WHERE ("addressbook_list_members"."list_id" = "addressbook_lists"."id"))))) AS "emails", array_to_string(ARRAY(SELECT DISTINCT unnest(array_agg("addressbook_list_members"."contact_id"))),',') AS "members", MIN("groups"."id") AS "group_id" FROM "tine20_addressbook_lists" AS "addressbook_lists"
         LEFT JOIN "tine20_addressbook_list_members" AS "addressbook_list_members" ON "addressbook_lists"."id" = "addressbook_list_members"."list_id"
         LEFT JOIN "tine20_groups" AS "groups" ON "addressbook_lists"."id" = "groups"."list_id" WHERE ("addressbook_lists"."is_deleted" = 0) AND ("addressbook_lists"."id" IN ('754dbb3408a4a335c5539ad176b987291f6b2cf3', 'b359363d39912398e2cca2aed96f5be51b3d3305', '549f3500378bc5678e1efd734de6dd08a9638187', 'd2a05652954c6768cecfea4679e293a42b0e7bbc', 'fef6534562e28e90997202c2a443b4af8a82f3a9', '19dbcedf67391d1ea020a6cf9454ca0e89bf0aed', '6742543a2b1f3f817042b5573098c422213ca634', '77b21379dc9e4202b89d4c8f5b8210fd940401cf', 'c308b2fc7fcdf66fda1d10cca31fc15029fc4d0d', '27a643c2bcda02c8e3bd05c93aec77e0d2c80eba', '61d0625b58a7c74ee176d7a009c21138428084fc')) AND ("addressbook_lists"."container_id" IN ('1') /* add acl in getMultiple */) GROUP BY "addressbook_lists"."id"
------------------------------------------------------------------------------------------------------------------------------------------------

Here is the EXPLAIN ANALYZE output of PostgreSQL:
------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=25542.51..25556.59 rows=11 width=609) (actual time=12110.574..12113.577 rows=11 loops=1)
   Group Key: addressbook_lists.id
   -> Hash Right Join (cost=39.88..186.47 rows=174 width=609) (actual time=0.940..10.111 rows=2208 loops=1)
         Hash Cond: ((addressbook_list_members.list_id)::text = (addressbook_lists.id)::text)
         -> Seq Scan on tine20_addressbook_list_members addressbook_list_members (cost=0.00..125.53 rows=5153 width=82) (actual time=0.005..3.074 rows=5153 loops=1)
         -> Hash (cost=39.74..39.74 rows=11 width=568) (actual time=0.916..0.916 rows=11 loops=1)
               Buckets: 1024 Batches: 1 Memory Usage: 11kB
               -> Hash Right Join (cost=17.57..39.74 rows=11 width=568) (actual time=0.369..0.904 rows=11 loops=1)
                     Hash Cond: ((groups.list_id)::text = (addressbook_lists.id)::text)
                     -> Seq Scan on tine20_groups groups (cost=0.00..20.14 rows=514 width=78) (actual time=0.006..0.227 rows=514 loops=1)
                     -> Hash (cost=17.43..17.43 rows=11 width=531) (actual time=0.319..0.319 rows=11 loops=1)
                           Buckets: 1024 Batches: 1 Memory Usage: 10kB
                           -> Seq Scan on tine20_addressbook_lists addressbook_lists (cost=0.00..17.43 rows=11 width=531) (actual time=0.020..0.305 rows=11 loops=1)
                                 Filter: ((is_deleted = '0'::numeric) AND ((container_id)::text = '1'::text) AND ((id)::text = ANY ('{754dbb3408a4a335c5539ad176b987291f6b2cf3,b359363d39912398e2cca2aed96f5be51b3d3305,549f3500378bc5678e1efd734de6dd08a9638187,d2a05652954c6768cecfea4679e293a42b0e7bbc,fef6534562e28e90997202c2a443b4af8a82f3a9,19dbcedf67391d1ea020a6cf9454ca0e89bf0aed,6742543a2b1f3f817042b5573098c422213ca634,77b21379dc9e4202b89d4c8f5b8210fd940401cf,c308b2fc7fcdf66fda1d10cca31fc15029fc4d0d,27a643c2bcda02c8e3bd05c93aec77e0d2c80eba,61d0625b58a7c74ee176d7a009c21138428084fc}'::text[])))
                                 Rows Removed by Filter: 317
   SubPlan 2
     -> Aggregate (cost=144.40..145.68 rows=1 width=17) (actual time=5.468..5.469 rows=1 loops=2208)
           -> Hash Semi Join (cost=44.67..144.36 rows=16 width=17) (actual time=1.069..3.300 rows=752 loops=2208)
                 Hash Cond: ((tine20_addressbook.id)::text = (addressbook_list_members_1.contact_id)::text)
                 -> Seq Scan on tine20_addressbook (cost=0.00..94.80 rows=1680 width=57) (actual time=0.001..0.825 rows=1615 loops=2208)
                 -> Hash (cost=44.47..44.47 rows=16 width=41) (actual time=1.048..1.048 rows=752 loops=2208)
                       Buckets: 2048 (originally 1024) Batches: 1 (originally 1) Memory Usage: 94kB
                       -> Bitmap Heap Scan on tine20_addressbook_list_members addressbook_list_members_1 (cost=4.53..44.47 rows=16 width=41) (actual time=0.114..0.565 rows=752 loops=2208)
                             Recheck Cond: ((list_id)::text = (addressbook_lists.id)::text)
                             Heap Blocks: exact=125053
                             -> Bitmap Index Scan on tine20_addressbook_list_members_pkey (cost=0.00..4.53 rows=16 width=0) (actual time=0.106..0.106 rows=752 loops=2208)
                                   Index Cond: ((list_id)::text = (addressbook_lists.id)::text)
           SubPlan 1
             -> HashAggregate (cost=0.76..1.26 rows=100 width=0) (actual time=0.914..1.233 rows=623 loops=2208)
                   Group Key: unnest(array_agg(tine20_addressbook.email))
                   -> Result (cost=0.00..0.51 rows=100 width=0) (actual time=0.001..0.380 rows=752 loops=2208)
   SubPlan 3
     -> HashAggregate (cost=0.76..1.26 rows=100 width=0) (actual time=0.255..0.340 rows=201 loops=11)
           Group Key: unnest(array_agg(addressbook_list_members.contact_id))
           -> Result (cost=0.00..0.51 rows=100 width=0) (actual time=0.001..0.103 rows=201 loops=11)
 Planning time: 1.777 ms
 Execution time: 12113.833 ms
(37 rows)
------------------------------------------------------------------------------------------------------------------------------------------------

Needless to say that syncing the contacts are failing now due to timeouts. What the f.... ist going on here?
TagsNo tags attached.
mwticket

Activities

nbe-renzel-net

nbe-renzel-net

2018-01-28 16:43

reporter   ~0021366

Well, my PostgreSQL dumps, which I'm doing every two hours, have become 140MB larger each. Resulting in a 3GB dump now. Thank you.

I've reverted to 2017.08.3
pschuele

pschuele

2018-03-15 14:42

administrator   ~0021522

do you still have this problem with the current release (2018.02.2)?

Issue History

Date Modified Username Field Change
2018-01-27 01:57 nbe-renzel-net New Issue
2018-01-28 16:43 nbe-renzel-net Note Added: 0021366
2018-03-15 14:42 pschuele Assigned To => pschuele
2018-03-15 14:42 pschuele Status new => feedback
2018-03-15 14:42 pschuele Note Added: 0021522