Opened 18 months ago

Last modified 18 months ago

#12863 new Bug/Something is broken

performance problems on lucius/owncloud server

Reported by: https://id.mayfirst.org/jamie Owned by:
Priority: Medium Component: Tech
Keywords: lucius owncloud Cc:
Sensitive: no

Description

I've noticed frequently spikes in cpu usage, which seem to be both disk i/o and cpu related.

I've also noticed the following:

  • The postgresql database has a huge pg_toast table, taking up most of the space of the database:
    owncloud=> SELECT nspname || '.' || relname AS "relation", pg_size_pretty(pg_relation_size(C.oid)) AS "size" FROM pg_class C LEFT JOIN pg_namespace N ON (N.oid = C.relnamespace) WHERE nspname NOT IN ('pg_catalog', 'information_schema') ORDER BY pg_relation_size(C.oid) DESC LIMIT 20;
                     relation                 |  size   
    ------------------------------------------+---------
     pg_toast.pg_toast_21027                  | 8464 MB
     public.oc_filecache                      | 344 MB
     public.oc_contacts_cards_properties      | 113 MB
     pg_toast.pg_toast_21027_index            | 93 MB
     public.fs_storage_path_hash              | 74 MB
     public.oc_contacts_cards                 | 70 MB
     public.cp_value_index                    | 69 MB
     public.fs_parent_name_hash               | 57 MB
     public.fs_storage_size                   | 51 MB
     public.cp_name_index                     | 40 MB
     public.oc_contacts_cards_properties_pkey | 30 MB
     public.cp_contactid_index                | 30 MB
     public.fs_storage_mimetype               | 28 MB
     public.fs_storage_mimepart               | 28 MB
     public.oc_filecache_pkey                 | 28 MB
     public.oc_documents_op                   | 25 MB
     public.oc_clndr_objects                  | 16 MB
     public.documents_op_eis_idx              | 14 MB
     public.oc_grauphel_notes                 | 10 MB
     public.category_object_index             | 8328 kB
    (20 rows)
    
    owncloud=> 
    
  • The postgres logs show the following error repeated over and over again:
    2017-06-21 20:59:41 EDT [18584-3] www-data@owncloud FATAL:  connection to client lost
    2017-06-21 20:59:41 EDT [18584-4] www-data@owncloud STATEMENT:  SELECT "id", "uri", "carddata", "lastmodified", "addressbookid" AS "parent", "fullname" AS "displayname" FROM "oc_contacts_cards" WHERE "addressbookid" = $1
    
  • The owncloud log has:
    {"reqId":"xxxxxxxxxxxxxxxx","remoteAddr":"xxxxxxxxxxxxx","app":"PHP","message":"Undefined index: addressBookId at \/var\/lib\/owncloud\/apps-local\/contacts\/lib\/hooks.php#109","level":3,"time":"2016-11-21T15:48:18+00:00"}
    

That last line appears tens of thousands of times in our log file - with only a handful of different IP addresses.

I suspect the last two may be related.

I have made the following code changes to at least avoid the errors:

0 lucius:/var/lib/owncloud/apps-local/contacts/lib# diff -u hooks.php.orig hooks.php
--- hooks.php.orig      2017-06-21 21:07:01.892245708 -0400
+++ hooks.php   2017-06-21 20:56:46.164103155 -0400
@@ -107,7 +107,9 @@
                $app = new App();
                $backend = $app->getBackend( (isset($parameters['backend'])) ? $parameters['backend'] :'local' );
                $ab = null;
-               $ab = $backend->getAddressBook( $parameters['addressBookId'] );
+               if (array_key_exists('addressBookId', $parameters)) {
+                       $ab = $backend->getAddressBook( $parameters['addressBookId'] );
+               }
 
                $contact = $parameters['contact'];
                if(isset($contact->CATEGORIES)) {
@@ -118,7 +120,9 @@
                                $tagMgr->tagAs($parameters['id'], $group);
                        }
                }
-               Utils\Properties::updateIndex($parameters['id'], $contact, $ab['owner']);
+               if ($ab) {
+                       Utils\Properties::updateIndex($parameters['id'], $contact, $ab['owner']);
+               }
        }
 
        public static function contactUpdated($parameters) {
1 lucius:/var/lib/owncloud/apps-local/contacts/lib#

Change History (5)

comment:1 Changed 18 months ago by https://id.mayfirst.org/jamie

And another pair of problems:

Postgres:

2017-06-21 21:04:56 EDT [19533-2] www-data@owncloud STATEMENT:  SELECT * FROM "oc_clndr_objects" WHERE "calendarid" = $1 AND "uri" = $2
2017-06-21 21:04:56 EDT [19536-1] www-data@owncloud ERROR:  invalid input syntax for integer: "contact_birthdays"
2017-06-21 21:04:56 EDT [19536-2] www-data@owncloud STATEMENT:  SELECT * FROM "oc_clndr_objects" WHERE "calendarid" = $1 AND "uri" = $2
2017-06-21 21:04:59 EDT [19549-1] www-data@owncloud ERROR:  invalid input syntax for integer: "contact_birthdays"
2017-06-21 21:04:59 EDT [19549-2] www-data@owncloud STATEMENT:  SELECT * FROM "oc_clndr_objects" WHERE "calendarid" = $1 AND "uri" = $2
2017-06-21 21:05:00 EDT [19550-1] www-data@owncloud ERROR:  invalid input syntax for integer: "contact_birthdays"
2017-06-21 21:05:00 EDT [19550-2] www-data@owncloud STATEMENT:  SELECT * FROM "oc_clndr_objects" WHERE "calendarid" = $1 AND "uri" = $2

owncloud.log:

{"reqId":"6B1lf8aHbPzS37eSRkuF","remoteAddr":"xx.xx.xx.xx","app":"caldav","message":"Exception: {\"Message\":\"An exception occurred while executing 'SELECT * FROM \\\"oc_clndr_objects\\\" WHERE \\\"calendarid\\\" = ? AND \\\"uri\\\" = ?' with params [\\\"contact_birthdays\\\", \\\"D290A225-ADE8-4547-8AD8-CD0A05D98273\\\"]:\\n\\nSQLSTATE[22P02]: Invalid text representation: 7 ERROR:  invalid input syntax for integer: \\\"contact_birthdays\\\"\",\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/DBALException.php(116): Doctrine\\\\DBAL\\\\Driver\\\\AbstractPostgreSQLDriver->convertException('An exception oc...', Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException))\\n#1 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Statement.php(172): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOPgSql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'SELECT * FROM \\\"...', Array)\\n#2 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/db\\\/statementwrapper.php(73): Doctrine\\\\DBAL\\\\Statement->execute(Array)\\n#3 \\\/var\\\/lib\\\/owncloud\\\/apps-local\\\/calendar\\\/lib\\\/object.php(104): OC_DB_StatementWrapper->execute(Array)\\n#4 \\\/var\\\/lib\\\/owncloud\\\/apps-local\\\/calendar\\\/lib\\\/sabre\\\/backend.php(381): OC_Calendar_Object::findWhereDAVDataIs('contact_birthda...', 'D290A225-ADE8-4...')\\n#5 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/CalDAV\\\/Calendar.php(163): OCA\\\\Calendar\\\\Sabre\\\\Backend->getCalendarObject('contact_birthda...', 'D290A225-ADE8-4...')\\n#6 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Tree.php(105): Sabre\\\\CalDAV\\\\Calendar->childExists('D290A225-ADE8-4...')\\n#7 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAVACL\\\/Plugin.php(758): Sabre\\\\DAV\\\\Tree->nodeExists('calendars\\\/alexd...')\\n#8 [internal function]: Sabre\\\\DAVACL\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#10 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(456): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#11 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#12 \\\/var\\\/lib\\\/owncloud\\\/apps-local\\\/calendar\\\/appinfo\\\/remote.php(60): Sabre\\\\DAV\\\\Server->exec()\\n#13 \\\/var\\\/www\\\/owncloud\\\/remote.php(137): require_once('\\\/var\\\/lib\\\/ownclo...')\\n#14 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractPostgreSQLDriver.php\",\"Line\":91}","level":4,"time":"2017-06-22T01:05:00+00:00"}

comment:2 Changed 18 months ago by https://id.mayfirst.org/jamie

I made the following change to avoid these last errors:

1 lucius:/var/lib/owncloud/apps-local/calendar/lib/sabre# diff -u backend.php.orig backend.php
--- backend.php.orig    2017-06-21 21:25:44.840311489 -0400
+++ backend.php 2017-06-21 21:26:06.484304320 -0400
@@ -377,6 +377,7 @@
                                        'calendardata' => $vevent->serialize()
                                ));
                        }
+                       return false;
                }
                $data = \OC_Calendar_Object::findWhereDAVDataIs($calendarId,$objectUri);
                if(is_array($data)) {
1 lucius:/var/lib/owncloud/apps-local/calendar/lib/sabre#

In short... \OC_Calendar_Object::findWhereDAVDataIs($calendarId,$objectUri); expects $calendarId to be an integer. However, in some cases it is set to the string 'contact_birthdays' - if that is the case, then return false rather than generate this error.

comment:3 Changed 18 months ago by https://id.mayfirst.org/jamie

See #12654 - regarding patch I made to the contacts module.

comment:4 Changed 18 months ago by https://id.mayfirst.org/jamie

I'm reading about toast tables and have written the following queries to find out which tables are storing data in the toast table:

owncloud=> select relname, reltoastrelid, oid from pg_class where reltoastrelid != 0;
           relname            | reltoastrelid |  oid  
------------------------------+---------------+-------
 pg_statistic                 |          2840 |  2619
 oc_appconfig                 |         20934 | 20929
 oc_bookmarks                 |         20948 | 20937
 pg_proc                      |          2836 |  1255
 pg_attrdef                   |          2830 |  2604
 pg_constraint                |          2832 |  2606
 pg_rewrite                   |          2838 |  2618
 pg_trigger                   |          2336 |  2620
 pg_description               |          2834 |  2609
 pg_db_role_setting           |          2966 |  2964
 pg_shdescription             |          2846 |  2396
 pg_seclabel                  |          3598 |  3596
 oc_clndr_calendars           |         20968 | 20957
 sql_implementation_info      |         11721 | 11719
 sql_languages                |         11726 | 11724
 sql_packages                 |         11731 | 11729
 oc_clndr_objects             |         20984 | 20973
 sql_sizing                   |         11741 | 11739
 sql_sizing_profiles          |         11746 | 11744
 oc_clndr_share_calendar      |         21003 | 20998
 oc_clndr_share_event         |         21010 | 21006
 oc_contacts_addressbooks     |         21022 | 21013
 oc_contacts_cards            |         21034 | 21027
 oc_contacts_cards_properties |         21047 | 21039
 sql_features                 |         11716 | 11714
 sql_parts                    |         11736 | 11734
 oc_documents_op              |         21070 | 21065
 oc_documents_revisions       |         21078 | 21075
 oc_documents_session         |         21084 | 21081
 oc_file_map                  |         21101 | 21094
 oc_files_trash               |         21133 | 21126
 oc_grauphel_notes            |         21149 | 21142
 oc_grauphel_oauth_tokens     |         21158 | 21154
 oc_jobs                      |         21189 | 21183
 oc_preferences               |         21527 | 21521
 oc_privatedata               |         21537 | 21530
 oc_properties                |         21549 | 21542
 oc_share                     |         21569 | 21554
 oc_share_external            |         21577 | 21572
 oc_filecache                 |         21121 | 21104
(40 rows)

The culprit seems to be the oc_contacts_cards table.

Last edited 18 months ago by https://id.mayfirst.org/jamie (previous) (diff)

comment:5 Changed 18 months ago by https://id.mayfirst.org/jamie

I think this all makes sense now. The oc_contacts_card table has a field called carddata which is a text field capable of storing encoded photos.

There are over 180,000 records in this table and I imagine a lot have photos and the huge size of that toast table is legit.

I think running VACUUM FULL oc_contacts_card may help reduce the size.

Please login to add comments to this ticket.

Note: See TracTickets for help on using tickets.