Parallelised request - no parallelism, but linear behaviour at server

Desktop
1

Hello,

Working today on bundling I discovered very strange thing, which I am not sure if it should work like that:

Steps to reproduce:
1. Install owncloud client
2. Install OC 9.1
3. Install mitmproxy
4. Run "mitmproxy -R http://localhost:9999";
5. In your ownCloud server, modify file /home/mrow4a/Projects/owncloud/apps/dav/lib/Connector/Sabre/File.php:
In function put, add sleep(5) before try -> It will delay every request for about 5s, while normal execution of the request on my PC is about 200ms.

public function put($data) {
sleep ( 5 );
try {
....

  1. Run owncloud client and configure it to connect to owncloud instance on http://localhost:8080"; (mitmproxy default port so that packets will be intercepted"
  2. Add like 10-20 files to your ownCloud folder localy, what will trigger sync

Expected:

Since we have max 3-5 parallel connection on the client, it is expected that 3 PUT will be executed in parallel, so that we shoud see sth like that:

Time | Operation | ExecutionTime
0 PUT 5s
0 PUT 5s
0 PUT 5s
5 PUT 5s
...
x PUT 5s

Actual behaviour please look at output.png, but in short:

output.png1920x1080 319 KB

Time | Operation | ExecutionTime
0 PUT 5s
0 PUT 10s
0 PUT 15s
5 PUT 15s
10 PUT 20s
15 PUT 10s
...
x PUT 15s

This means only one thing:
* Yes - on the client we are creating at instant 3 parallel connections
* Yes - it is designed to do so
* It means, that the 3 parallel requests are arriving to the server at the same time, are queued, and executed one by one, taking consequetively 5, 10 and 15 second for 1,2 and 3 request.

Question here - is it real parallelism of the requests desired, or just optimizing the way of delivering them to the server buffer, so reducing effect of latency? But anyways, why do we keep 2 out of 3 request waiting at the server not executing them?

Are you able to reproduce that?

Piotr

2

A Database engine matters here. SQlite is not good from the point of concurrency.

3

How is database engine involved, if I just delayed the request doing sleep() at the begining. I observed this behaviour doing my bundled request:

Time | Operation | ExecutionTime
0 POST 50s
20 PROPFIND 30s
30 GET status.php 20s

Which will mean, that propfind and simple GET status.php has been waiting for POST to finish

4

I suspected that this is related, but doing session_write_close() did not really help:

http://konrness.com/php5/how-to-prevent-blocking-php-requests/

Anyways, why do we block simple request like GET status.php and PROPFIND with other requests. Or why do we use parallel request if they are not really parallel?

5

@mrow4a the time value displayed here, is that the time where the request was started or ended ?

When I first saw these values, I had the impression that the desktop client was first creating a single request, then another single one, and only after 2 successful requests it would send 3 parallelized ones. Not sure why though.

The server should not behave in a linear way. If you see this, maybe it's because of unclosed sessions. I remember that in the past we had to explicitly close the session in PHP in some requests to make sure it unblocks other parallel requests. Closing the session as in "telling PHP that we're not going to write anything else to it but keeping read-only access".

6

@PVince81 are you able to reproduce my problem using mitmproxy? Just observe the request flow with PUTs having them delayed with sleep()

EDIT:
@PVince81
These TIME values are just dummy, I can give you real data. Look on EXECUTION TIME, this is important there - look on the appended picture. This time was only to give impression what happened

7

I've never used mitmproxy. Just did a test by adding logging before and after the sleep:

{"reqId":"J0Wrb90OSjJ\/WqhJmlOI","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: before sleep for $path=\"\/\/1368555495004.jpg\" $name=\"1368555495004.jpg\"","level":0,"time":"2016-10-13T19:26:31+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/1368555495004.jpg","user":"admin"}
{"reqId":"z7DTno\/8h0PklUtZy3u0","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: before sleep for $path=\"\/\/1391249528060.jpg\" $name=\"1391249528060.jpg\"","level":0,"time":"2016-10-13T19:26:31+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/1391249528060.jpg","user":"admin"}
{"reqId":"DWOL\/nazhl1cdwklru5a","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: before sleep for $path=\"\/\/20110610_005.jpg\" $name=\"20110610_005.jpg\"","level":0,"time":"2016-10-13T19:26:31+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/20110610_005.jpg","user":"admin"}
{"reqId":"J0Wrb90OSjJ\/WqhJmlOI","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: after sleep for $path=\"\/\/1368555495004.jpg\" $name=\"1368555495004.jpg\"","level":0,"time":"2016-10-13T19:26:36+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/1368555495004.jpg","user":"admin"}
{"reqId":"z7DTno\/8h0PklUtZy3u0","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: after sleep for $path=\"\/\/1391249528060.jpg\" $name=\"1391249528060.jpg\"","level":0,"time":"2016-10-13T19:26:36+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/1391249528060.jpg","user":"admin"}
{"reqId":"DWOL\/nazhl1cdwklru5a","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: after sleep for $path=\"\/\/20110610_005.jpg\" $name=\"20110610_005.jpg\"","level":0,"time":"2016-10-13T19:26:36+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/20110610_005.jpg","user":"admin"}
{"reqId":"idxMewPm+iG\/uksrNtAX","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: before sleep for $path=\"\/\/20130317_001.jpg\" $name=\"20130317_001.jpg\"","level":0,"time":"2016-10-13T19:26:37+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/20130317_001.jpg","user":"admin"}
{"reqId":"eGf6+CwErHl4H6WShleb","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: before sleep for $path=\"\/\/DSC05207.JPG\" $name=\"DSC05207.JPG\"","level":0,"time":"2016-10-13T19:26:37+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/DSC05207.JPG","user":"admin"}
{"reqId":"KmFLPdScNJ9ek1mdF4EP","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: before sleep for $path=\"\/\/DSC_0158.JPG\" $name=\"DSC_0158.JPG\"","level":0,"time":"2016-10-13T19:26:37+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/DSC_0158.JPG","user":"admin"}
{"reqId":"idxMewPm+iG\/uksrNtAX","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: after sleep for $path=\"\/\/20130317_001.jpg\" $name=\"20130317_001.jpg\"","level":0,"time":"2016-10-13T19:26:42+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/20130317_001.jpg","user":"admin"}
{"reqId":"eGf6+CwErHl4H6WShleb","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: after sleep for $path=\"\/\/DSC05207.JPG\" $name=\"DSC05207.JPG\"","level":0,"time":"2016-10-13T19:26:42+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/DSC05207.JPG","user":"admin"}
{"reqId":"KmFLPdScNJ9ek1mdF4EP","remoteAddr":"127.0.0.1","app":"DEBUG","message":"DEBUG: after sleep for $path=\"\/\/DSC_0158.JPG\" $name=\"DSC_0158.JPG\"","level":0,"time":"2016-10-13T19:26:42+00:00","method":"PUT","url":"\/owncloud\/remote.php\/webdav\/DSC_0158.JPG","user":"admin"}

When looking at the log with tail, I saw the three "before sleep" appearing at the same time and also "after sleep" at the same time after 5 seconds. So parallelism seems to work here.

This was with MySQL.

8

Simple patch here, to apply on top of v9.1.1:

diff --git a/apps/dav/lib/Connector/Sabre/File.php b/apps/dav/lib/Connector/Sabre/File.php
index 6ecb6e6..0b7458c 100644
--- a/apps/dav/lib/Connector/Sabre/File.php
+++ b/apps/dav/lib/Connector/Sabre/File.php
@@ -85,6 +85,9 @@ class File extends Node implements IFile {
         * @return string|null
         */
        public function put($data) {
+               \OC::$server->getLogger()->debug('DEBUG: before sleep for $path="' . $this->getPath() . '" $name="' . $this->getName() . '"', array('app' => 'DEBUG'));
+               sleep(5);
+               \OC::$server->getLogger()->debug('DEBUG: after sleep for $path="' . $this->getPath() . '" $name="' . $this->getName() . '"', array('app' => 'DEBUG'));
                try {
                        $exists = $this->fileView->file_exists($this->path);
                        if ($this->info && $exists && !$this->info->isUpdateable()) {
9

For me looking on debug from your patch is still locking, without mitmproxy . Could it be xdebug or something else?

10

I have xdebug enabled too here. Try with Mysql.
My setup:
apache2-2.4.23-3.1.x86_64
php5-5.6.24-1.1.x86_64

11

But I have mysql MariaDB, apache2 and php5.6

12

Ok, I have tested it with another server I installed on pure ubuntu and it works perfectly with parallelisation.

The problem exists only on my local computer, but still trying to understand what could be the cause

13

@PVince81 @DeepDiver1975 Ok, I have found an issue.

I have been running a server using:

"ocdev server --port 9999" in a folder /home/mrow4a/Projects/owncloud, so my local folder.

Just in case someone will run in the same issue. On the same machine, running ownCloud in /var/www using traditional way, parallelisation is running perfectly