Performance regression with JIT?

[9128305]

Hi, i see performance slowdown when using JIT.

import os
import sys
from dataclasses import dataclass

from django.conf import settings
from django.core.wsgi import get_wsgi_application
from django.http import HttpResponseRedirect, JsonResponse
from django.urls import path
from django.utils.crypto import get_random_string

settings.configure(
    DEBUG=(os.environ.get("DEBUG", "") == "1"),
    ALLOWED_HOSTS=["*"],
    ROOT_URLCONF=__name__,
    SECRET_KEY=get_random_string(50),
    MIDDLEWARE=["django.middleware.common.CommonMiddleware"],
)


@dataclass
class Character:
    name: str
    age: int

    def as_dict(self, id_):
        return {
            "id": id_,
            "name": self.name,
            "age": self.age,
        }


characters = {
    1: Character("Rick Sanchez", 70),
    2: Character("Morty Smith", 14),
}


def index(request):
    return HttpResponseRedirect("/characters/")


def characters_list(request):
    return JsonResponse(
        {"data": [character.as_dict(id_) for id_, character in characters.items()]}
    )


def characters_detail(request, character_id):
    try:
        character = characters[character_id]
    except KeyError:
        return JsonResponse(
            status=404,
            data={"error": f"Character with id {character_id!r} does not exist."},
        )
    return JsonResponse({"data": character.as_dict(character_id)})


urlpatterns = [
    path("", index),
    path("characters/", characters_list),
    path("characters/<int:character_id>/", characters_detail),
]

app = get_wsgi_application()

import cinderx.jit
cinderx.jit.auto()

Run with

uvx --python 3.14 --with cinderx --with django gunicorn app:app --workers 2

Test with

oha http://127.0.0.1:8000/characters/ -n 10000

Results without jit:

Summary:
  Success rate: 100.00%
  Total:        2313.5602 ms
  Slowest:      23.8704 ms
  Fastest:      2.4653 ms
  Average:      11.5360 ms
  Requests/sec: 4322.3426

  Total data:   986.33 KiB
  Size/request: 101 B
  Size/sec:     426.32 KiB

Response time histogram:
   2.465 ms [1]    |
   4.606 ms [3]    |
   6.746 ms [4]    |
   8.887 ms [8]    |
  11.027 ms [6089] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  13.168 ms [1247] |■■■■■■
  15.308 ms [1507] |■■■■■■■
  17.449 ms [817]  |■■■■
  19.589 ms [254]  |■
  21.730 ms [52]   |
  23.870 ms [18]   |

Response time distribution:
  10.00% in 9.3260 ms
  25.00% in 9.5303 ms
  50.00% in 10.5114 ms
  75.00% in 13.3903 ms
  90.00% in 15.5463 ms
  95.00% in 16.6522 ms
  99.00% in 18.9686 ms
  99.90% in 22.4369 ms
  99.99% in 23.0650 ms


Details (average, fastest, slowest):
  DNS+dialup:   0.0498 ms, 0.0228 ms, 0.9485 ms
  DNS-lookup:   0.0045 ms, 0.0020 ms, 0.1850 ms

Status code distribution:
  [200] 10000 responses

With jit:

Summary:
  Success rate: 100.00%
  Total:        3258.2137 ms
  Slowest:      380.4819 ms
  Fastest:      2.4534 ms
  Average:      16.2516 ms
  Requests/sec: 3069.1664

  Total data:   986.33 KiB
  Size/request: 101 B
  Size/sec:     302.72 KiB

Response time histogram:
    2.453 ms [1]    |
   40.256 ms [9944] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
   78.059 ms [5]    |
  115.862 ms [0]    |
  153.665 ms [0]    |
  191.468 ms [0]    |
  229.270 ms [0]    |
  267.073 ms [0]    |
  304.876 ms [0]    |
  342.679 ms [48]   |
  380.482 ms [2]    |

Response time distribution:
  10.00% in 12.1094 ms
  25.00% in 12.4133 ms
  50.00% in 13.3456 ms
  75.00% in 16.2191 ms
  90.00% in 18.3394 ms
  95.00% in 19.7645 ms
  99.00% in 35.0709 ms
  99.90% in 338.9049 ms
  99.99% in 363.0008 ms


Details (average, fastest, slowest):
  DNS+dialup:   0.0546 ms, 0.0230 ms, 1.0392 ms
  DNS-lookup:   0.0049 ms, 0.0021 ms, 0.1698 ms

Status code distribution:
  [200] 10000 responses

Am I doing something wrong? cinderx.jit.force_compile(characters_list) does not help.

[filips123]

I haven't properly benchmarked it, but from a few quick manual tests, I think I have the same problem with Flask app served using Apache Mod WSGI.

[alexmalyshev]

I'm seeing the same thing on my end. You're not doing anything wrong, we're still missing some optimizations (Python frame management) and build configuration settings from our internal build (e.g. LTO/PGO). We'll be following up on this in the coming weeks.

[DinoV]

So I've started looking into this. A few things immediately stand out:

1. There's a lot of time spent in the initial JITing of this run. If you run oha two times in a row you'll see things warmed up and the numbers do look a lot better. You can kind of see this standing out here as the slowest request being 380ms.
2. The fastest response occurs with the JIT. On my machine after 2 runs w/ and w/o the JIT the w/o JIT fastest was 2.68ms and w/ the JIT was 1.83ms. Yours look about the same here but I also see a big speed up from the first to second run too.
3. There's definitely some hot spots show up. The first thing is in our inline caches for method loads we're not handling classes which define __getattr__ well - these are occuring on things like gunicorn Config.__getattr__, asgiref Local.__getattr__, and django LazyObject.__getattribute__. This causes us to spin through the cache and miss and do a full lookup every time. I'm hoping this is an easyish fix. Another thing is there's a good amount of exceptions being thrown which are causing deopt's. That's definitely more involved.

I'm going to try and fix the load method cache and see what stands behind it. Longer term we're working on moving things to do re-compilation and specialization which would probably help a lot here.

[DinoV]

Digging further into the caches I ran with CINDERX_JIT_ENABLE_INLINE_CACHE_STATS=1 and dumping cinderx.jit.get_and_clear_inline_cache_stats() at the end. This is on top of a build w/ some fixes to handle __getattr__ and __getattribute__ better. There's lots of cache misses that are being hit once per request.

• Dotting through a package to a submodule 'module.module.func() - for example the call to format_date in gunicorn/util.py in http_date. We will try and turn things into a module specific access if we can but here we don't follow through the multiple dots.
• Dotting through a module to a member on a type - module.type.func() - For example the call to fromtimestamp in email/utils.py in formatdate. Similar to the module case.
• Calls to static methods - e.g. URLResolver._join_route
• Calls to non-methods - e.g. RequestParser.mesg_class
• Calls to classmethod_descriptor e.g. int.from_bytes(...) -

So there's numerous reasons why the caches are missing and showing up as hot. But it doesn't go far enough in explaining the performance gap - the caches are still only less than 5% and the delta between JIT and no-jit is much larger.