python3: "sql" test suite passing slowed down

[ImeevMA]

With python3:

time ./test-run.py sql/ --force

Result:

real	0m36.403s
user	1m15.925s
sys	0m17.432s

With python2:

python2 time ./test-run.py sql/ --force

Result:

real	0m12.975s
user	0m45.623s
sys	0m16.097s

[Totktonada]

$ time python2 ./test/test-run.py --conf memtx sql/boolean.test.sql
<...>
real	0m0.849s
user	0m0.849s
sys	0m0.224s
$ time python3 ./test/test-run.py --conf memtx sql/boolean.test.sql
<...>
real	0m4.653s
user	0m4.733s
sys	0m0.271s

[Totktonada]

$ time python3 ./test/test-run.py --conf memtx sql/boolean.test.sql -j -1
real	0m0.919s
user	0m0.810s
sys	0m0.113s

[Totktonada]

Disable logs:

diff --git a/lib/colorer.py b/lib/colorer.py
index 8c867c1..4b5b7e5 100644
--- a/lib/colorer.py
+++ b/lib/colorer.py
@@ -214,7 +214,8 @@ class Colorer(object):
         if self.queue:
             if self.queue_msg_wrapper:
                 obj = self.queue_msg_wrapper(obj, log_only)
-            self.queue.put(obj)
+            if not log_only:
+                self.queue.put(obj)
         elif not log_only:
             self.stdout.write(obj)

Run:

$ time python3 ./test/test-run.py --conf memtx sql/boolean.test.sql
<...>
real	0m0.947s
user	0m0.823s
sys	0m0.133s

It seems something is not good with the speed of the worker -> main process queue.

[Totktonada]

Don't process results from a worker in the main process:

diff --git a/dispatcher.py b/dispatcher.py
index e0053d4..e6d6d0f 100644
--- a/dispatcher.py
+++ b/dispatcher.py
@@ -333,9 +333,9 @@ class Dispatcher:
                 objs.append(result_queue.get())
 
         # process received objects
-        for obj in objs:
-            for listener in self.listeners:
-                listener.process_result(obj)
+        #for obj in objs:
+        #    for listener in self.listeners:
+        #        listener.process_result(obj)
 
         return objs

Run:

$ time python3 ./test/test-run.py --conf memtx sql/boolean.test.sql
<...>
real	0m1.034s
user	0m1.163s
sys	0m0.132s

So listeners are not so fast to process everything that workers are generate.

Obvious optimization point: write per-worker logs directly, without passing over the queue. There is no reason to write them from the main process, because each worker has its own log.

However it is still interesting why the listeners in the main process became so slow on Python 3.

[Totktonada]

Ensure Options is a signleton on Python 3:

diff --git a/lib/options.py b/lib/options.py
index 7daebcb..ad97984 100644
--- a/lib/options.py
+++ b/lib/options.py
@@ -23,11 +23,10 @@ def env_list(name, default):
     return value_list or default
 
 
-class Options:
+# XXX: It is Python 3 only.
+class Options(metaclass=Singleton):
     """Handle options of test-runner"""
 
-    __metaclass__ = Singleton
-
     def __init__(self):
         """Add all program options, with their defaults."""

Run:

$ time python3 ./test/test-run.py --conf memtx sql/boolean.test.sql
<...>
real	0m0.855s
user	0m0.879s
sys	0m0.139s

We should find a good way to create a singleton on Python 2 and Python 3 both.

Where to look for recipes:

• https://github.com/PythonCharmers/python-future/blob/4657ad23de79a541ebcc7a06f1b9ad60172ad3c4/src/future/utils/__init__.py#L114-L146
• https://github.com/benjaminp/six/blob/42636b15dd1a5b85de56eac98e47954d4c776576/six.py#L846-L885