[Cubicweb] Feedback on rqlcontroller

Jinpeng Li mr.li.jinpeng at gmail.com
Fri Jun 13 10:48:56 CEST 2014


Hi Aurélien,

Sorry for the late reply. Recently, I found that I need to solve this
problem otherwise rqlcontroller is not reliable. It happens often on my
laptop and the server as well.

I appreciate any help and suggestion. Thanks in advance.


0. Scripts
==========

Database schema (schema.py):
----------------
```python
class Study(EntityType):
    """ The study """
    identifier = String(required=True, fulltextindexed=True,
                        indexed=True, maxsize=64)
```

Import script (test_rql.py):
--------------
```python
import json
import uuid
from datetime import datetime

try:
    # ensure a recent request lib is available
    import requests
    assert [int(n) for n in requests.__version__.split('.', 2)][:2] >= [1,
2]
except (ImportError, AssertionError):
    requests = None

if __name__ == "__main__":
    # Create a session that with authentication
    base_url = 'http://localhost:8080'
    r = requests.Session()
    a = r.get(base_url + "?__login=admin&__password=admin")
    print a.status_code
    for i in xrange(10000):
        # Insert a data
        print "=" * 30
        print "step %d" % i
        identifier = uuid.uuid4()
        args = [('INSERT Study S: S identifier "%(identifier)s"'
                 % dict(identifier=str(identifier)),
                 {}), ]
        time1 = datetime.now()
        a = r.post(base_url + "/rqlio/1.0",
                   data=json.dumps(args),
                   headers={'Content-Type': 'application/json'})
        time2 = datetime.now()
        diff = time2 - time1
        print "It takes ", diff.microseconds, " microseconds"
        output_rql = a.json()[0]
        print a.status_code
        print output_rql
```

Benchmark script (benchmark_mem.sh):
-------------------------

```sh
while true; do
ps -C cubicweb-ctl -o pid=,%mem=,vsz=,%cpu= >> /tmp/mem.log
sleep 1
done
```

1. Experiment on importation
==============

Start the server by:

```
$ cubicweb-ctl start -D itest_rqlcontroller
```

Start the benchmark script (benchmark_mem.sh):

```
$ source benchmark_mem.sh
```

Start the importation script (test_rql.py):

```
$ python test_rql.py
```


2. Experiment output
================


The tail log information when it freezes.

server output:
-------------------

```
................
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in 0.0
sec
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: no login/password in form params
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: publish "/rqlio/1.0"
(admin41b1a129689d453887be4e6bedf216d6, form params: [])
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: not a static file uri:
/rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no simple rewrite rule
found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no schemabased rewrite
rule found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: precommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: postcommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: commit session
admin41b1a129689d453887be4e6bedf216d6 done (no db activity)
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in 0.0
sec
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: no login/password in form params
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: publish "/rqlio/1.0"
(admin41b1a129689d453887be4e6bedf216d6, form params: [])
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: not a static file uri:
/rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no simple rewrite rule
found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no schemabased rewrite
rule found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: precommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: postcommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: commit session
admin41b1a129689d453887be4e6bedf216d6 done (no db activity)
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in 0.0
sec
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: no login/password in form params
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: publish "/rqlio/1.0"
(admin41b1a129689d453887be4e6bedf216d6, form params: [])
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: not a static file uri:
/rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no simple rewrite rule
found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no schemabased rewrite
rule found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: precommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: postcommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: commit session
admin41b1a129689d453887be4e6bedf216d6 done (no db activity)
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in
0.00999999999999 sec
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: no login/password in form params
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: publish "/rqlio/1.0"
(admin41b1a129689d453887be4e6bedf216d6, form params: [])
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: not a static file uri:
/rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no simple rewrite rule
found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no schemabased rewrite
rule found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: precommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: postcommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: commit session
admin41b1a129689d453887be4e6bedf216d6 done (no db activity)
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in 0.0
sec
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: no login/password in form params
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: publish "/rqlio/1.0"
(admin41b1a129689d453887be4e6bedf216d6, form params: [])
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: not a static file uri:
/rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no simple rewrite rule
found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no schemabased rewrite
rule found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: precommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: postcommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: commit session
admin41b1a129689d453887be4e6bedf216d6 done (no db activity)
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in
0.01 sec
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: no login/password in form params
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: publish "/rqlio/1.0"
(admin41b1a129689d453887be4e6bedf216d6, form params: [])
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: not a static file uri:
/rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no simple rewrite rule
found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.appobject) DEBUG: no schemabased rewrite
rule found for /rqlio/1.0
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: precommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: postcommit session
admin41b1a129689d453887be4e6bedf216d6 done
2014-06-13 10:20:09 - (cubicweb.repository) DEBUG: begin commit for session
admin41b1a129689d453887be4e6bedf216d6
2014-06-13 10:20:09 - (cubicweb.session) DEBUG: commit session
admin41b1a129689d453887be4e6bedf216d6 done (no db activity)
2014-06-13 10:20:09 - (cubicweb.web) DEBUG: query rqlio/1.0 executed in 0.0
sec
```

benchmark_mem.sh
-------------------
-o pid=,%mem=,vsz=,%cpu=
```
10547  1.5 638312 12.0
10547  1.5 638312 10.6
10547  1.5 638312  9.7
10547  1.5 638312  8.8
10547  1.5 638312  8.1
10547  1.5 638312  7.5
10547  1.5 638312  7.0
10547  1.5 638312  6.6
10547  1.5 638312  6.2
10547  1.5 638312  5.8
10547  1.5 712176  6.7
10547  1.5 712408  9.2
10547  1.5 712408 11.8
10547  1.5 712408 14.3
10547  1.5 712408 16.4
10547  1.5 712408 17.7
10547  1.5 712408 19.4
10547  1.5 712408 21.0
10547  1.5 712408 22.5
10547  1.5 712408 23.1
10547  1.5 712408 24.3
10547  1.5 712408 25.5
10547  1.6 712408 26.5
10547  1.6 712408 27.5
10547  1.6 712408 28.3
10547  1.6 712408 29.2
10547  1.6 712408 29.6
10547  1.6 712408 30.3
10547  1.6 712408 30.8
10547  1.6 712408 31.7
10547  1.6 712408 32.3
10547  1.6 712408 33.1
10547  1.6 712408 33.5
10547  1.6 712408 34.1
10547  1.6 712680 34.6
10547  1.6 712680 35.2
10547  1.6 712680 35.7
10547  1.6 712680 36.3
10547  1.6 712680 36.8
10547  1.6 712680 37.2
10547  1.6 712680 37.7
10547  1.6 712680 38.2
10547  1.6 712680 38.4
10547  1.6 712680 38.8
10547  1.6 712680 39.1
10547  1.6 712680 39.5
10547  1.6 712680 39.9
10547  1.7 712680 40.2
10547  1.7 712680 40.6
10547  1.7 712680 40.7
10547  1.7 712680 41.0
10547  1.7 712680 41.3
10547  1.7 712680 41.4
10547  1.7 786412 41.7
10547  1.7 786412 41.9
10547  1.7 786412 42.1
10547  1.7 786412 42.4
10547  1.7 786412 42.7
10547  1.7 786412 42.9
10547  1.7 786412 43.2
10547  1.7 786412 43.5
10547  1.7 786412 43.7
10547  1.7 786412 43.9
10547  1.7 786412 44.1
10547  1.7 786412 44.2
10547  1.7 786412 44.3
10547  1.7 786412 44.5
10547  1.7 786412 44.6
10547  1.8 786668 44.8
10547  1.8 786668 45.1
10547  1.8 786668 45.3
10547  1.8 786668 45.5
10547  1.8 786668 45.6
10547  1.8 786668 45.8
10547  1.8 786668 46.0
10547  1.8 786668 46.1
10547  1.8 786668 46.1
10547  1.8 786668 46.2
10547  1.8 786668 46.4
10547  1.8 786668 46.6
10547  1.8 786668 46.8
10547  1.8 786668 46.7
10547  1.8 786668 46.9
10547  1.8 786668 47.0
10547  1.8 786668 47.2
10547  1.8 786668 47.3
10547  1.8 786668 46.9
10547  1.8 786924 47.0
10547  1.9 786924 47.1
10547  1.9 786924 47.3
10547  1.9 786924 47.5
10547  1.9 786924 47.5
10547  1.9 786924 47.5
10547  1.9 786924 47.6
10547  1.9 786924 47.7
10547  1.9 786924 47.8
10547  1.9 786924 47.9
10547  1.9 786924 48.0
10547  1.9 786924 48.1
10547  1.9 786924 48.2
10547  1.9 786924 48.3
10547  1.9 786924 48.4
10547  1.9 786924 48.5
10547  1.9 786924 48.5
10547  1.9 786924 48.7
10547  1.9 786924 48.7
10547  1.9 786924 48.8
10547  1.9 786924 48.9
10547  1.9 786924 49.0
10547  1.9 786924 49.1
10547  1.9 786924 49.1
10547  1.9 786924 49.1
10547  1.9 786924 49.2
10547  1.9 786924 49.3
10547  1.9 786924 49.3
10547  1.9 786924 49.4
10547  1.9 786924 49.5
10547  1.9 786924 49.5
10547  1.9 786924 49.6
10547  1.9 786924 49.6
10547  2.0 786924 49.7
10547  2.0 786924 49.7
10547  2.0 786924 49.8
10547  2.0 786924 49.9
10547  2.0 786924 50.0
10547  2.0 786924 50.0
10547  2.0 786924 50.1
10547  2.0 786924 50.2
10547  2.0 786924 50.2
10547  2.0 786924 50.3
10547  2.0 786924 50.4
10547  2.0 786924 50.4
10547  2.0 786924 50.5
10547  2.0 786924 50.6
10547  2.0 786924 50.6
10547  2.0 786924 50.7
10547  2.0 786924 50.7
10547  2.0 786924 50.8
10547  2.0 786924 50.9
10547  2.0 786924 50.9
10547  2.0 786924 51.0
10547  2.0 786924 51.0
10547  2.0 786924 51.1
10547  2.0 786924 51.1
10547  2.0 786924 51.1
10547  2.0 786924 51.1
10547  2.0 786924 51.1
10547  2.0 786924 51.2
10547  2.0 786924 51.3
10547  2.0 786924 51.2
10547  2.0 786924 51.3
10547  2.0 786924 51.0
10547  2.0 786924 51.1
10547  2.0 786924 51.1
10547  2.0 786924 51.2
10547  2.0 786924 51.2
10547  2.0 786924 51.3
10547  2.0 786924 51.3
10547  2.0 786924 51.3
10547  2.0 786924 51.2
10547  2.0 786924 51.2
10547  2.0 786924 51.2
10547  2.0 786924 51.3
10547  2.0 786924 51.2
10547  2.0 786924 51.2
10547  2.0 786924 51.2
10547  2.0 786924 51.2
10547  2.0 786924 51.3
10547  2.0 786924 51.2
10547  2.0 786924 51.3
10547  2.0 786924 51.3
10547  2.0 860656 51.2
10547  2.0 860656 51.3
10547  2.0 860656 51.2
10547  2.0 860656 51.2
10547  2.0 860656 51.2
10547  2.0 860656 51.2
10547  2.0 860656 51.2
10547  2.0 860656 51.2
10547  2.0 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.2
10547  2.1 860656 51.3
10547  2.1 860656 51.3
10547  2.1 860656 51.3
10547  2.1 860656 51.3
10547  2.1 860656 51.3
10547  2.1 860912 51.3
10547  2.1 860912 51.3
10547  2.1 860912 51.3
10547  2.1 860912 51.3
10547  2.1 860912 51.3
10547  2.1 861168 51.3
10547  2.1 861168 51.3
10547  2.1 861168 51.3
10547  2.1 861168 51.3
10547  2.1 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.2
10547  2.2 861168 51.2
10547  2.2 861168 51.2
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.2
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.3
10547  2.2 861168 51.1
10547  2.2 861168 50.9 <- Freeze approximately here
10547  2.2 861168 50.7
10547  2.2 861168 50.5
10547  2.2 861168 50.3
10547  2.2 861168 50.1
10547  2.2 861168 49.7
10547  2.2 861168 49.5
10547  2.2 861168 49.3
10547  2.2 861168 49.1
10547  2.2 861168 49.0
10547  2.2 861168 48.8
10547  2.2 861168 48.6
10547  2.2 861168 48.4
10547  2.2 861168 48.2
10547  2.2 861168 48.0
```

test_rql.py
--------------
```
.....
==============================
step 8145
It takes  16552  microseconds
200
[[8921]]
==============================
step 8146
It takes  16465  microseconds
200
[[8922]]
==============================
step 8147
It takes  16429  microseconds
200
[[8923]]
==============================
step 8148
It takes  16563  microseconds
200
[[8924]]
==============================
step 8149
It takes  16577  microseconds
200
[[8925]]
==============================
step 8150
It takes  17723  microseconds
200
[[8926]]
==============================
step 8151
It takes  15339  microseconds
200
[[8927]]
==============================
step 8152
It takes  16759  microseconds
200
[[8928]]
==============================
step 8153
It takes  16349  microseconds
200
[[8929]]
==============================
step 8154
It takes  16723  microseconds
200
[[8930]]
==============================
step 8155
It takes  16203  microseconds
200
[[8931]]
==============================
step 8156

freezing...
```

My conclusion
===========

The memory and cpu consumption are still low.  I can restart test_rql.py to
continue import data which means the server is not broken. There are only
8155 entities in the database which is a small dataset. This bug could be
easily reproduced within 5 minutes.

The script stops at waiting for the response from http server after post.
```
        a = r.post(base_url + "/rqlio/1.0",
                   data=json.dumps(args),
                   headers={'Content-Type': 'application/json'})
```

I think there is a bug that sending back response on the http server. Any
suggestion will be appreciated.

Thanks and regards,
Jinpeng


On Tue, May 20, 2014 at 5:51 PM, Aurélien Campéas <
aurelien.campeas at logilab.fr> wrote:

> On 20/05/2014 17:37, Jinpeng Li wrote:
> > Hi Cubicweb Team,
>
> Hi Jinpeng,
>
> >
> > Just let you know my feedback on rqlcontroller.
>
> Thanks,
>
> >
> > Therefore recently I imported all the data using rqlcontroller over
> > http(s). It works very well for small set of data. However, considering
> > a large data set, sometimes I fail to get response after I post data to
> > the server. It may be caused by too frequent http-post on cubicweb
> > server. Or rqlcontroller try to protect server from DOS attack. Or it is
> > a problem in /requests. /I found a solution that I need to set up a
> > timeout parameter for the /requests/ to avoid unlimited waiting.  Please
> > see the example as below. The test script and server is running on the
> > same machine. The network is stable. I hope this feedback is useful for
> you.
> >
>
> Looks like you just wrote a kind of benchmark & stress test :)
> We want more of these !
>
> Could you just compute the time it takes to compute each request to
> this script ? It could give interesting hints and show slow-downs
> happening while you hammer the instance.
>
> At the same time, watching the overall instance memory consumption
> would be interesting.
>
> Regards,
> Aurélien.
>
> _______________________________________________
> Cubicweb mailing list
> Cubicweb at lists.cubicweb.org
> http://lists.cubicweb.org/mailman/listinfo/cubicweb
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.cubicweb.org/pipermail/cubicweb/attachments/20140613/1c6c7f4e/attachment-0001.html>


More information about the Cubicweb mailing list