Disabling encryption running extremely slow

Hello!

TL:DR:

occ encryption:decrypt-all running super slow (2-3 seconds for each few KB file)

I’ve been using ownCloud since the very beginning and switched to NextCloud after it was released. Since this particular instance should hold my and my families data I thought it would be a good idea to enable the encryption. But it was always a pain in the butt - especially on ownCloud upgrades. The NextCloud upgrades went way smoother but still there were always hiccups on the way.
2 days ago I decided that I don’t want to deal with these issues anymore and think of another way. So I went ahead and figured out how to remove the encryption. According to what I’ve found running occ encryption:decrypt-all would set the instance to maintenance, decrypt all files and disable encryption. So I took a backup and started the process sudo -u www-data php occ encryption:decrypt-all. It found my 4 hours and started decrypting the files without any error messages.
The issue I’m now facing is that the decryption is running veeeeeery slow. About 2-3 seconds for a few KB large file. At this rate it would take weeks to decrypt all my data.

  1. Is this slow speed normal?
  2. How can I speed up the process?
  3. Can I interrupt the process and restart it later in case any configuration changes would provide a speed improvement?

System details:

Nextcloud version: 18.0.1.3
Operating system and version: 16.04.6 LTS (Xenial Xerus)
Apache or nginx version: Apache/2.4.41 (Ubuntu)
PHP version: 7.3.15-3 (FPM/FastCGI)

Server hardware:

The server is a dedicated root server with quite beefy hardware:

The EX40 dedicated root server houses a high-performance Intel® Core i7-4770 Quad-Core processor of the well-known Haswell architecture and 32 GB DDR3 RAM. Furthermore, two 2 TB SATA 6 Gb/s Enterprise HDDs are used. Both hard drives are specially designed for sustained rapid growth in data volume. They also guarantee high reliability during continuous operation.
RAM: 32 GB DDR3 RAM
Hard Drive: 2 x 2 TB SATA 6 Gb/s 7200 rpm HDD (Software-RAID 1) Class Enterprise

CPU

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                8
On-line CPU(s) list:   0-7
Thread(s) per core:    2
Core(s) per socket:    4
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 60
Model name:            Intel(R) Xeon(R) CPU E3-1246 v3 @ 3.50GHz
Stepping:              3
CPU MHz:               3823.066
CPU max MHz:           3900.0000
CPU min MHz:           800.0000
BogoMIPS:              7000.19
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              8192K
NUMA node0 CPU(s):     0-7
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm xsaveopt dtherm ida arat pln pts

RAM: 32GB
Hard disk hdparm:

/dev/md2:
 Timing cached reads:   29886 MB in  2.00 seconds = 14958.83 MB/sec
 Timing buffered disk reads: 114 MB in  3.05 seconds =  37.43 MB/sec

The output of my Nextcloud file:

{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:56:59+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:05+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:05+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:05+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:08+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:08+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:08+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:10+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:10+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:10+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:12+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:12+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:12+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:15+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:15+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:15+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:17+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:17+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:17+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:20+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:20+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:20+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:22+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:22+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:22+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:24+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"stream_wrapper_register(): Protocol ocencryption:// is already defined. at /var/www/x22889/cloud/lib/private/Files/Stream/Encryption.php#203","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:24+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#760","userAgent":"--","version":"18.0.1.3"}
{"reqId":"zrlDBZRTYuaCUQCyKSC5","level":3,"time":"2020-03-07T14:57:24+01:00","remoteAddr":"","user":"--","app":"PHP","method":"","url":"--","message":"fclose() expects parameter 1 to be resource, string given at /var/www/x22889/cloud/lib/private/Files/Storage/Wrapper/Encryption.php#761","userAgent":"--","version":"18.0.1.3"}

The output of your config.php file in /path/to/nextcloud (make sure you remove any identifiable information!):

<?php
$CONFIG = array (
  'activity_expire_days' => 14,
  'auth.bruteforce.protection.enabled' => true,
  'blacklisted_files' =>
  array (
    0 => '.htaccess',
    1 => 'Thumbs.db',
    2 => 'thumbs.db',
  ),
  'instanceid' => 'xxx',
  'passwordsalt' => 'xxx',
  'trusted_domains' =>
  array (
    0 => 'cloud.example.com',
    1 => 'example.com',
  ),
  'datadirectory' => '/var/www/oc_data',
  'dbtype' => 'mysql',
  'version' => '18.0.1.3',
  'dbname' => 'dbname',
  'dbhost' => 'localhost',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'dbusr',
  'dbpassword' => 'dbpw',
  'installed' => true,
  'enable_previews' => true,
  'enabledPreviewProviders' =>
  array (
    0 => 'OC\\Preview\\PNG',
    1 => 'OC\\Preview\\JPEG',
    2 => 'OC\\Preview\\GIF',
    3 => 'OC\\Preview\\BMP',
    4 => 'OC\\Preview\\XBitmap',
    5 => 'OC\\Preview\\Movie',
    6 => 'OC\\Preview\\PDF',
    7 => 'OC\\Preview\\MP3',
    8 => 'OC\\Preview\\TXT',
    9 => 'OC\\Preview\\MarkDown',
  ),
  'loglevel' => 2,
  'log_rotate_size' => 104857600,
  'logtimezone' => 'Europe/Berlin',
  'theme' => '',
  'maintenance' => true,
  'forcessl' => true,
  'mail_smtpmode' => 'smtp',
  'mail_from_address' => 'cloud',
  'mail_domain' => 'example.com',
  'secret' => 'xxx',
  'forceSSLforSubdomains' => false,
  'singleuser' => false,
  'trashbin_retention_obligation' => 'auto',
  'filelocking.enabled' => 'true',
  'debug' => false,
  'overwrite.cli.url' => 'https://cloud.example.com',
  'mail_sendmailmode' => 'smtp',
  'mail_smtphost' => 'x22889.de',
  'mail_smtpsecure' => 'tls',
  'mail_smtpport' => '25',
  'app_install_overwrite' =>
  array (
    0 => 'calendar',
  ),
  'mysql.utf8mb4' => true,
  'updater.release.channel' => 'stable',
  'updater.secret' => 'xxx',
);

This text will be hidden
The output of your Apache/nginx/system log in /var/log/____:

Logs for this subdomain are not logging anything

Thanks,
Stefan

It seems a bit long, I suppose the access to file before was much faster?

Did you check the processes during the time? Is CPU or RAM maxing out? Or i/o-operations?
Perhaps the database? I hope you put the server in maintenance mode so there are no other access requests via users.

File access was always fast - only thumbnail generation usually took a while (few seconds).

The process is still running but CPU utilization is quite low - the decryption process rarely shows up as a top process. RAM isn’t fully utilized either:

top - 22:29:09 up 1187 days, 5:02, 1 user, load average: 2.32, 2.42, 2.33
Tasks: 353 total, 1 running, 352 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2.3 us, 0.6 sy, 0.0 ni, 85.3 id, 11.9 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 32806332 total, 9023000 free, 11027148 used, 12756184 buff/cache
KiB Swap: 16768892 total, 12910008 free, 3858884 used. 20939136 avail Mem

The decrypt-all command does place the instance in maintenance mode automatically so user access isn’t an issue.

This is the i/o-wait. With i/o-top you can check the processes using all the i/o. Could be the database that is updated, and regarding the database it can make a huge difference to optimize the database-cache settings. In recent versions, they added a few database indexes (you have to add them with an occ-command).

You don’t use any memory caches, that will make a noticeable difference in the web interface (not sure for the decryption process).

However, all things you can’t change during the process running. I don’t know if you can stop the process and resume later. You could try and check to find more information in the documentation or somewhere in the bugtracker. If you have a backup from just before the decryption (and you are sure it is working), you could stop the current process and rely on your backup.

To bring at least some clarification / closure to this:

tflidd pointed me into the right direction with the i/o load. After some digging I figured that jbd2/md2-8 was causing >95 io wait / load on my hard drives. So far I wasn’t able to pin it down exactly but it’s somehow related to MySQL / ext4. Will have to do some more investigation later on.

Since I couldn’t get a clear statement if the decryption process could be interrupted I let it run for a couple of days. At least it went through without any issues. Although I have to download all my files again (see https://github.com/nextcloud/server/issues/7283).

The mentioned database indexes were all set (at least none were showing as missing in Administration -> Overview -> Security & setup warnings.

I was using a file cache until a PHP update decided to upgrade my version from 7.2 to 7.4 (which wasn’t supported by NextCloud 17) and things went tits up. So I postponed re-configuring a filecache until NextCloud 18 was released.

So, thanks again to tflidd for the help!

Regards,
Stefan