`arcade.gl.query.__exit__` extremely slow

[eschan145]

Bug Report

When profiling my code, I found out that arcade.gl.query.__exit__ was taking up the vast majority of my performance time, more than four times than anything else. It doesn't seem right that an __exit__ function should take this long, and my project is running slowly because of this. I'm surprised this hasn't been brought up before, and it may be a problem with my code.

         5219230 function calls (5174575 primitive calls) in 49.182 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    35634   15.204    0.000   15.364    0.000 C:\Users\Esamu\AppData\Roaming\Python\Python312\site-packages\arcade\gl\query.py:132(__exit__)
     2899    3.393    0.001    4.267    0.001 {built-in method time.sleep}
    35634    3.323    0.000    3.456    0.000 C:\Users\Esamu\AppData\Roaming\Python\Python312\site-packages\arcade\gl\vertex_array.py:342(transform_interleaved)
     4332    1.925    0.000    1.985    0.000 {built-in method nt._getfinalpathname}

System Info

Arcade 3.0.0.dev35
------------------
vendor: Intel
renderer: Intel(R) UHD Graphics
version: (3, 3)
python: 3.12.2 (tags/v3.12.2:6abddd9, Feb  6 2024, 21:26:36) [MSC v.1937 64 bit (AMD64)]
platform: win32
pyglet version: 2.1.dev5
PIL version: 10.2.0

Steps to reproduce/example code:

My project is located at https://github.com/eschan145/SpaceShooter.

[DragonMoffon]

Thanks for bringing this to our attention. The link to your repository doesn't work at the mo. Secondly, I wonder if you could also provide the top functions by the highest average time rather than the highest total time given that the method was called 30000+ times, which means each call takes around 0.5 ms to complete (admittedly not insignificant but it will be interesting to see the slowest methods aswell)

[Cleptomania]

I strongly suspect this isn’t anything Arcade can really do about it. My guess is this is just the result of the GL querying being slow, querying blocks the pipeline in GL and is generally a pretty expensive operation to perform. Would need more in depth profiling to determine the exact function call eating the bulk of the time, but I strongly suspect that it’s one of the GL query operations.

If it is that, the performance can vary a decent bit between different hardware/drivers as well.

[DragonMoffon]

It's unsurprising that this particular exit method takes a while. multiple gl calls are made per property queried. Given that these are getting information directly from the GPU, they are probably blocking methods, which will cause your program to hang until the GPU responds. If you are querying large or complex gl operations such as data transfers, then you will have to wait for that whole process to finish rather than continuing immediately and letting it complete in the background.

From my investigation, no internal arcade process uses the Query object, so if it isn't critical to your applications functionality, it might be better to disable it when not debugging.

[einarf]

It likely needs to wait for the rendering queue to process the call you are measuring to obtain the query info. If there are many things already in the queue it also needs to wait for those to complete.

[eschan145]

Thanks for your responses. I've fixed the repo link, so it should work now. Run profiler.py to see the profiling results.

Secondly, I wonder if you could also provide the top functions by the highest average time rather than the highest total time given that the method was called 30000+ times, which means each call takes around 0.5 ms to complete (admittedly not insignificant but it will be interesting to see the slowest methods aswell)

cProfile doesn't support sorting by time percall. And most of the ones that take up the most time aren't really revelant anyways, because they are only called once. However, the update function of the main game takes about 0.026 seconds to complete and is called 163 times, but that's really all that's significant.

From my investigation, no internal arcade process uses the Query object, so if it isn't critical to your applications functionality, it might be better to disable it when not debugging.

I tried commenting it out, but collision checking stopped working. Are you referring to something else? output.txt

[eschan145]

It seems it's being called when checking for collisions. I've added custom collision detection using AABBs and it has replaced arcade.gl.query as the slowest method.

[DragonMoffon]

You are correct sorry, the reference finder didn't pick that up. If you are using GPU collisions for sprites then it does have a query object. That shouldn't be running by default I'll look into it.

[DragonMoffon]

def _get_nearby_sprites(
    sprite: BasicSprite, sprite_list: SpriteList[SpriteType]
) -> List[SpriteType]:
    sprite_count = len(sprite_list)
    if sprite_count == 0:
        return []

    # Update the position and size to check
    ctx = get_window().ctx
    sprite_list._write_sprite_buffers_to_gpu()

    ctx.collision_detection_program["check_pos"] = sprite.position
    ctx.collision_detection_program["check_size"] = sprite.width, sprite.height

    # Ensure the result buffer can fit all the sprites (worst case)
    buffer = ctx.collision_buffer
    if buffer.size < sprite_count * 4:
        buffer.orphan(size=sprite_count * 4)

    # Run the transform shader emitting sprites close to the configured position and size.
    # This runs in a query so we can measure the number of sprites emitted.
    with ctx.collision_query:
        sprite_list._geometry.transform(  # type: ignore
            ctx.collision_detection_program,
            buffer,
            vertices=sprite_count,
        )

    # Store the number of sprites emitted
    emit_count = ctx.collision_query.primitives_generated
    # print(
    #     emit_count,
    #     ctx.collision_query.time_elapsed,
    #     ctx.collision_query.time_elapsed / 1_000_000_000,
    # )

    # If no sprites emitted we can just return an empty list
    if emit_count == 0:
        return []

    # # Debug block for transform data to keep around
    # print("emit_count", emit_count)
    # data = buffer.read(size=emit_count * 4)
    # print("bytes", data)
    # print("data", struct.unpack(f'{emit_count}i', data))

    # .. otherwise build and return a list of the sprites selected by the transform
    return [
        sprite_list[i] for i in struct.unpack(f"{emit_count}i", buffer.read(size=emit_count * 4))
    ]

[DragonMoffon]

Yikes... so query is needed hahaha

[einarf]

We really need to to a pass on collision in the future. Remember that you can also specify the collision method to override the default behavior. IF you try to do collision in very large lists without spatial hash the gpu version will trigger. That's of course not always what you want but it's still a useful option.