--gc:orc --threads:on slower than --threads:off

[UNIcodeX]

Firstly: Thank you for working on this project. It is a wonderful framework to use, and I am using it in production, rather than Jester.

The issue: The bit of code below is slower with threads than without, when built using orc.

NOTE: The issue is also present when NOT using a {.threadvar.} although less pronounced than with {.threadvar.}. resp htmlResponse("<h2>Welcome to Prologue</h2>"): Non-threadvar single-thread: 28970 req/s Non-threadvar multi-thread: 16319 req/s (1.7x slower)

threadvar single-thread: 22371 req/s threadvar multi-thread: 6406 req/s (3.49x slower)

Nim version (latest devel)

nim --version
Nim Compiler Version 1.5.1 [Linux: amd64]
Compiled at 2020-10-16
Copyright (c) 2006-2020 by Andreas Rumpf

git hash: 6b8baab536d25c744150e0190d2e172165faf92e
active boot switches: -d:release

system info:

OS: Arch Linux 
Kernel: x86_64 Linux 5.8.8-arch1-1
CPU: Intel Core i5-6200U @ 4x 2.8GHz [41.0°C]
GPU: Intel Corporation Skylake GT2 [HD Graphics 520] (rev 07)
RAM: 5680MiB / 15739MiB

Testing with wrk -t2 -c100 -d10s http://localhost:8000

Using --gc:orc (multi-threaded has lower throughput)

nim c -r -d:danger -d:release --opt:speed --gc:orc main

Running 10s test @ http://localhost:8000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     4.93ms    3.56ms  85.98ms   82.41%
    Req/Sec    11.27k     0.93k   13.46k    76.50%
  224424 requests in 10.03s, 104.45MB read
Requests/sec:  22371.13
Transfer/sec:     10.41MB

nim c -r -d:danger -d:release --opt:speed --gc:orc --threads:on main

Running 10s test @ http://localhost:8000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    17.24ms   12.43ms 110.90ms   87.82%
    Req/Sec     3.23k   413.09     4.39k    81.50%
  64325 requests in 10.04s, 29.94MB read
Requests/sec:   6406.63
Transfer/sec:      2.98MB

Using --gc:markAndSweep (multi-threaded has more throughput as expected)

nim c -r -d:danger -d:release --opt:speed --gc:markAndSweep main

Running 10s test @ http://localhost:8000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     3.59ms    1.89ms 101.07ms   98.98%
    Req/Sec    14.21k     1.29k   15.80k    94.50%
  282931 requests in 10.03s, 131.67MB read
Requests/sec:  28206.92
Transfer/sec:     13.13MB

nim c -r -d:danger -d:release --opt:speed --gc:markAndSweep --threads:on main

Running 10s test @ http://localhost:8000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     2.12ms    1.75ms  23.15ms   90.73%
    Req/Sec    26.01k     1.72k   29.89k    68.50%
  517948 requests in 10.04s, 241.05MB read
Requests/sec:  51598.09
Transfer/sec:     24.01MB

Example code:

import prologue
import nwt

let settings = newSettings(
  address="0.0.0.0",
  debug=false,
  port=Port(8000),
  staticDirs=["/static"],
)

var app = newApp(settings=settings)

## Set up threadvar for `templates` for per thread initialization.
var templates {.threadvar.} : Nwt

proc initTemplates() =
  if templates.isNil:
    templates = newNwt("templates/*.html")

proc index(ctx: Context) {.gcsafe, async.} =
  initTemplates()
  resp templates.renderTemplate("index.html")

app.addRoute("/", index)

app.run()

[ringabout]

Thanks for choosing Prologue famework :)

You should look at this issue: https://github.com/nim-lang/Nim/issues/14224. I guess ORC still needs improvement.

Did some testing of nimforum with ORC both single-threaded/multi-threaded. In single-threaded mode nimforum with ORC seems to leak ~3mb per 95k requests. In multi-threaded mode nimforum with ORC is ~3.5x SLOWER than single-threaded, and leaks orders > of magnitude more (~800MB RAM for 26k requests) - with other GCes like refc or markAndSweep > multi-threaded performance is of course much better than single-threaded. It really seems to me that httpbeast and ORC don't like each other at all

If you have any question, you could ask me in discord: https://discord.gg/e2dB4WT

Prologue will release 0.4.0 and contains many changes. For examples, static file serving will become middlewares.

import prologue
import prologue/middlewares/staticfile
import nwt

let settings = newSettings(
  address="0.0.0.0",
  debug=false,
  port=Port(8000)
)

var app = newApp(settings=settings, middlewares = staticFileMiddleware(["/static"]))
# or
# var app = newApp(settings=settings)
# app.use(staticFileMiddleware(["/static"]))

## Set up threadvar for `templates` for per thread initialization.
var templates {.threadvar.} : Nwt

proc initTemplates() =
  if templates.isNil:
    templates = newNwt("templates/*.html")

proc index(ctx: Context) {.gcsafe, async.} =
  initTemplates()
  resp templates.renderTemplate("index.html")

app.addRoute("/", index)

app.run()

Btw, user can extend their own Context in 0.4.0. But I'm still thinking about a better way. https://gist.github.com/xflywind/62ac7a29e40016261c2ff046791493ed

[UNIcodeX]

Thank you for the reply. Good information to know! And thanks for the Discord invitation (I joined it immediately).

The user defined context extension reminds me of Python decorators. Very cool.

[UNIcodeX]

While we're talking about middlewares, is there a possible way of using a library that doesn't support threading inherently (say anonimongo) with prologue, in threaded mode, by perhaps making use of the middleware functionality, or some other trickery?

[ringabout]

I don't think so. The library must be thread-safe to be used with Prologue.

[UNIcodeX]

Alright. I had started putting this together when I saw your reply in Discord.

This is scaled down and changed from some production code, to use {.threadvar.} and thread-local initialization procs.

import os
import re
import json
import times
import strformat
import strutils
import parsecfg
import sequtils
import algorithm
import logging
import asyncdispatch

import timeit
import oids
import anonimongo
import anonimongo/core/bson
import prologue
import nwt

import ./helpers

#[ Logging ~ ]#
var
  logFmtStr  = "$levelname [$date @ $time]: "
  consoleLog = newConsoleLogger(fmtStr=logFmtStr)
  logLevel   : logging.Level

logging.addHandler(consoleLog)

when defined(debug) or defined(test):
  logLevel = logging.lvlDebug
when defined prod:
  logLevel = logging.lvlError
#[ Logging ~ ]#

#[ Config ~ ]#
var
  configFileName  {.threadvar.} : string
  cfg             {.threadvar.} : <//>Config
  # MongoDB
  mongoConnString {.threadvar.} : string
  # WebService
  port            {.threadvar.} : Port
  debug           {.threadvar.} : bool
  appName         {.threadvar.} : string
  staticDirs      {.threadvar.} : string
  secretKey       {.threadvar.} : string

proc initConfig() =
  if cfg.isNil:
    when defined(production) or defined(prod):
      let configFileName = "config.ini"
    else:
      let configFileName = "configTest.ini"
    cfg             = loadConfig(configFileName)
    # MongoDB
    mongoConnString = cfg.getSectionValue("MongoDB", "connString")
    # WebService
    port            = parseInt(cfg.getSectionValue("WebService", "port")).Port
    debug           = parseBool(cfg.getSectionValue("WebService", "debug"))
    appName         = cfg.getSectionValue("WebService", "appName")
    staticDirs      = cfg.getSectionValue("WebService", "staticDirs")
    secretKey       = cfg.getSectionValue("WebService", "secretKey")

# init config so main thread will have web service params
initConfig()
#[ ~ Config ]#

#[ MongoDB ~ ]#
var
  mongo    {.threadvar.} : Mongo
  db       {.threadvar.} : Database
  collTest {.threadvar.} : Collection

proc initMongo() =
  initConfig()
  if mongo.isNil:
    mongo = newMongo()
    mongo = newMongo(MongoUri(mongoConnString))

    if not waitfor mongo.connect:
    logging.fatal "MongoDB: Cannot connect to domain-host"
    quit 1
    else:
    logging.info "MongoDB: Connected!"

    if not waitfor mongo.authenticate[:Sha256Digest]():
    logging.warn "MongoDB: Could not authenticate with SHA256. Trying SHA1. You should really update MongoDB!"
    if not waitfor mongo.authenticate[:SHA1Digest]():
      logging.fatal "Cannot login to domain-host"
      quit 1
    else:
      logging.info "MongoDB: Authenticated with SHA1. This is not secure."
    else:
    logging.info "MongoDB: Authenticated with SHA256!"

    db       = mongo["LamiNation"]
    collTest = db["query"]
#[ ~ MongoDB ]#

proc jsonResponse*(s: string, code = Http200, headers = newHttpHeaders(),
    version = HttpVer11): Response {.inline.} =
  headers["Content-Type"] = "application/json"
  result = initResponse(version, code, headers, body = s)

#[ Routes ~ ]#
let
  settings = newSettings(
    appName = appName,
    debug = debug,
    port = port,
    staticDirs = [staticDirs],
    secretKey = secretKey
  )

proc queryDB(ctx: Context) {.gcsafe, async.} =
  initMongo()
  let pipeline = @[
    bson({ 
      "$match": 
        { active: true } 
      }), 
    bson({
      "$project": {
        "id": {
          "$toString": "$_id"
        },
        "_id": 0,  
        "URI": 1, 
        "active": 1, 
        "bgImageURI": 1, 
        "bgPosition": 1, 
        "bgSize": 1, 
        "hasButton": 1,
        "buttonColor": 1, 
        "buttonText": 1, 
        "buttonTextColor": 1, 
        "buttonWidth": 1, 
        "displayTime": 1, 
        "hasHeadline": 1,
        "headlineText": 1, 
        "headlineTextColor": 1
      }
    })
  ]
  let query = await collTest.aggregate(pipeline)
  resp jsonResonse ($query).strip(chars={'@'}, leading=true)

#[ ~ Routes ]#

var app = newApp(settings = settings)

if debug or logLevel == logging.lvlDebug:
  logLevel = lvlDebug
else:
  logLevel = lvlInfo

setLogFilter(logLevel)

app.addRoute("/queryDB", queryDB, @[HttpGet, HttpPost])

app.run()

[disruptek]

I would run your performance test against https://github.com/nim-lang/Nim/pull/15588 and see if the results differ.

[UNIcodeX]

I was excited there for a second, but sadly the issue persists.

$ choosenim update self
$ choosenim update devel
   Updating devel
Downloading Nim 2020-10-19-devel-78cbb52fa01d6c73307fe276bdf7d4c34d7a556c-2 from GitHub
[##################################################] 100.0% 0kb/s
 Extracting nim-1.5.1-2-linux_x64.tar.xz
    Setting up git repository
   Building Nim #devel
  Compiler: Already built
     Tools: Already built
    Updated to #devel
      Info: Version #devel already selected

$ nim --version
Nim Compiler Version 1.5.1 [Linux: amd64]
Compiled at 2020-10-19
Copyright (c) 2006-2020 by Andreas Rumpf

git hash: 78cbb52fa01d6c73307fe276bdf7d4c34d7a556c
active boot switches: -d:release

nim c -r -d:danger -d:release --opt:speed --gc:orc main

Running 10s test @ http://localhost:8000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     5.21ms    3.72ms  70.41ms   80.02%
    Req/Sec    10.72k     0.91k   12.38k    81.50%
  213441 requests in 10.04s, 99.33MB read
Requests/sec:  21254.98
Transfer/sec:      9.89MB

nim c -r -d:danger -d:release --opt:speed --gc:orc --threads:on main

Running 10s test @ http://localhost:8000
  2 threads and 100 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    17.02ms   11.34ms  89.19ms   87.47%
    Req/Sec     3.22k   365.96     4.37k    79.00%
  64041 requests in 10.04s, 29.80MB read
Requests/sec:   6380.90
Transfer/sec:      2.97MB

[UNIcodeX]

Even tried with the following, thinking maybe the nightly didn't have the change yet. choosenim update devel --latest

nim --version
Nim Compiler Version 1.5.1 [Linux: amd64]
Compiled at 2020-10-19
Copyright (c) 2006-2020 by Andreas Rumpf

git hash: 833035bacd91c2cf16ea006b64bf996e87eac75d
active boot switches: -d:release

Same disparity in r/s

[disruptek]

Okay, thanks for testing it. Do we have a compiler issue for this? If not, please create an issue specifically for this performance problem. I'm assuming that the first code snippet is a reliable reproduction; that's correct, right? We don't need the mongo version?

[UNIcodeX]

For sure.

I'm not sure whether an issue similar to this exists on the compiler repo. The initial snippet is all that is required to reproduce. No need for Mongo code.

How should I go about opening the issue on the Nim repo? just mention it and cross reference this one? Or should I copy the whole example and also link to this thread?

[HugoP707]

This also happen with the other gc's iirc

[UNIcodeX]

@RecruitMain707 See the full OP. markAndSweep is quite a bit faster with threads than without. This is an arc/orc issue as confirmed by disruptek.

[UNIcodeX]

https://github.com/nim-lang/Nim/issues/15661