benchmark: several minor changes

- add fileserver logs, write them to file (--logfile)
- put bench results into file (--out-file)
- silence requests.packages.urllib3.connectionpool logger
- fix cputime metric for preexisting splash instances

splash/benchmark/benchmark.py

@@ -11,12 +11,13 @@
 import logging
 import os
 import random
-from argparse import ArgumentDefaultsHelpFormatter, ArgumentParser
+from argparse import ArgumentDefaultsHelpFormatter, ArgumentParser, FileType
 from glob import glob
 from multiprocessing.pool import ThreadPool
 from pprint import pformat
 from time import time
 import re
+import sys
 
 import requests
 from splash.benchmark.file_server import serve_files
@@ -67,8 +68,9 @@ def make_render_png_lua_req(splash, params):
 PORT = 8806
 #: Combinations of width & height to test.
 WIDTH_HEIGHT = [(None, None), (500, None), (None, 500), (500, 500)]
-#: Splash log filename (set to None to put it to stdout).
+#: Splash & fileserver log filenames (set to None to put it to stderr).
 SPLASH_LOG = 'splash.log'
+FILESERVER_LOG = 'fileserver.log'
 #: This script is used to collect maxrss & cpu time from splash process.
 GET_PERF_STATS_SCRIPT = """
 function main(splash)
@@ -88,16 +90,19 @@ def make_render_png_lua_req(splash, params):
                     help='Directory with downloaded sites')
 parser.add_argument('--splash-server', metavar='HOST:PORT',
                     help='Use existing Splash instance available at HOST:PORT')
+parser.add_argument('--out-file', type=FileType(mode='w'), default=sys.stdout,
+                    help='Write detailed request information in this file')
 
 
 def generate_requests(splash, args):
     log = logging.getLogger('generate_requests')
     log.info("Using pRNG seed: %s", args.seed)
 
     # Static pages (relative to sites_dir) to be used in the benchmark.
-    pages = [re.sub('^%s/' % args.sites_dir, '', v)
-             for v in glob(os.path.join(args.sites_dir, 'localhost_8806',
-                                        '*.html'))]
+    log.info("sites dir: %s", args.sites_dir)
+    sites_found = glob(os.path.join(args.sites_dir, 'localhost_8806', '*.html'))
+    log.info("sites found: %s", sites_found)
+    pages = [re.sub('^%s/' % args.sites_dir.rstrip('/'), '', v) for v in sites_found]
     for p in pages:
         log.info("Using page for benchmark: %s", p)
 
@@ -160,6 +165,7 @@ def __exit__(self, *args):
 def main():
     log = logging.getLogger("benchmark")
     args = parser.parse_args()
+    logging.getLogger('requests.packages.urllib3.connectionpool').setLevel(logging.WARNING)
     logging.basicConfig(level=logging.DEBUG)
 
     if args.splash_server:
@@ -171,18 +177,28 @@ def main():
                         '--disable-xvfb',
                         '--max-timeout=600'])
 
-    with splash, serve_files(port=PORT, directory=args.sites_dir):
+    with splash, serve_files(port=PORT, directory=args.sites_dir, logfile=FILESERVER_LOG):
+        log.info("Servers are up, starting benchmark...")
+        start_res = requests.get(
+            splash.url('execute'),
+            params={'lua_source': GET_PERF_STATS_SCRIPT}).json()
         start_time = time()
         results = parallel_map(invoke_request, generate_requests(splash, args),
                                args.thread_count)
         end_time = time()
-        resources = requests.get(
+        end_res = requests.get(
             splash.url('execute'),
             params={'lua_source': GET_PERF_STATS_SCRIPT}).json()
 
-    log.info("Request stats:\n%s", pformat(dict(enumerate(results))))
-    log.info("Splash max RSS: %s B", resources['maxrss'])
-    log.info("Splash CPU time elapsed: %.2f sec", resources['cputime'])
+    log.info("Writing stats to %s", args.out_file.name)
+    args.out_file.write(pformat({
+                'maxrss': end_res['maxrss'],
+                'cputime': end_res['cputime'] - start_res['cputime'],
+                'walltime': end_time - start_time,
+                'requests': results}))
+    log.info("Splash max RSS: %s B", end_res['maxrss'])
+    log.info("Splash CPU time elapsed: %.2f sec",
+             end_res['cputime'] - start_res['cputime'])
     log.info("Wallclock time elapsed: %.2f sec", end_time - start_time)
 
 

splash/benchmark/file_server.py

@@ -6,27 +6,35 @@
 import os
 import subprocess
 import time
+import sys
 from contextlib import contextmanager
 
 from twisted.internet import reactor
 from twisted.web.server import Site
 from twisted.web.static import File
+from twisted.python.log import startLogging
 
 import requests
 
 parser = argparse.ArgumentParser("")
-parser.add_argument('--port', type=int)
-parser.add_argument('--directory', help='Directory to be served')
-
+parser.add_argument('--port', type=int, default=8806)
+parser.add_argument('--directory', help='Directory to be served', default='.')
+parser.add_argument('--logfile', default=sys.stderr, type=argparse.FileType(mode='w'), 
+                    help='File to write logs to')
 
 @contextmanager
 def serve_files(port, directory, logfile=None):
     """Serve files from specified directory statically in a subprocess."""
-    command = ['twistd',
-               '-n',    # don't daemonize
-               'web',   # start web component
+    # command = ['twistd',
+    #            '-n',    # don't daemonize
+    #            'web',   # start web component
+    #            '--port', str(int(port)),
+    #            '--path', os.path.abspath(directory), ]
+    # if logfile is not None:
+    #     command += ['--logfile', logfile]
+    command = ['python', __file__,
                '--port', str(int(port)),
-               '--path', os.path.abspath(directory), ]
+               '--directory', os.path.abspath(directory)]
     if logfile is not None:
         command += ['--logfile', logfile]
     site_server = subprocess.Popen(command)
@@ -46,6 +54,7 @@ def serve_files(port, directory, logfile=None):
 
 def main():
     args = parser.parse_args()
+    startLogging(args.logfile)
     resource = File(os.path.abspath(args.directory))
     site = Site(resource)
     reactor.listenTCP(args.port, site)

splash/qtrender_lua.py

@@ -497,7 +497,7 @@ def get_perf_stats(self):
         rss_mul = 1 if sys.platform == 'darwin' else 1024
         return {'maxrss': rusage.ru_maxrss * rss_mul,
                 'cputime': rusage.ru_utime + rusage.ru_stime,
-                'walltime': time.time()}
+                 'walltime': time.time()}
 
     def get_real_exception(self):
         if self._exceptions: