search

CleverRaven / Cataclysm-DDA

Cataclysm - Dark Days Ahead. A turn-based survival game set in a post-apocalyptic world.
http://cataclysmdda.org
Other
9.95k stars 4.08k forks source link

Trying to fall asleep next to a tree is incredibly slow, but waiting is not #73552

Open NetSysFire opened 2 months ago

NetSysFire commented 2 months ago

Describe the bug

There are no nearby monsters either.

I ran the game in gdb to see what it was doing:

Thread 1 (Thread 0x7ffff748f7c0 (LWP 1664080) "cataclysm-tiles"):
#0  0x0000555555e8816c in trig_dist () at src/line.h:159
No locals.
#1  rl_dist () at src/line.h:184
No locals.
#2  0x0000555556b324d3 in cast_horizontal_zlight_segment<1, 0, 0, 1, 1, float, &(sight_calc(float const&, float const&, int const&)), &(sight_check(float const&, float const&)), &(accumulate_transparency(float const&, float const&, int const&))> () at src/shadowcasting.cpp:298
No locals.
#3  0x0000555556b371ac in cast_zlight<float, &(sight_calc(float const&, float const&, int const&)), &(sight_check(float const&, float const&)), &(accumulate_transparency(float const&, float const&, int const&))> () at src/shadowcasting.cpp:607
No locals.
#4  0x000055555655ef65 in map::build_seen_cache () at src/lightmap.cpp:1019
No locals.
#5  0x00005555565d5b27 in map::build_map_cache () at src/map.cpp:9591
No locals.
#6  0x00005555561ca439 in do_turn () at src/do_turn.cpp:655
No locals.
#7  0x0000555555ccb9df in main () at src/main.cpp:868

Weird. I tried sleeping outside of the improvised shelter but no dice. Wild guess: treetops? I know these would do z-level shading things. And indeed going just a bit west into the open makes this issue go away.

Attach save file

Innawoods-trimmed.tar.gz

Reproducible by trying to sleep adjacent to a tree.

Steps to reproduce

(While the save is obviously an innawoods one, I highly doubt this is mod specific)

  1. Load save.
  2. Try to sleep.
  3. The progress is excruciating slow.
  4. Cancel and see if waiting is faster.
  5. Waiting is indeed blazingly fast.
  6. Go a bit west, away from trees.
  7. Try sleeping again on the floor.
  8. It is fast.

Expected behavior

Falling asleep progresses as fast as waiting under tree tops.

CC @PatrikLundell since you did a lot of tree tops related things and might know whats going on here.

Screenshots

No response

Versions and configuration

Additional context

No response

PatrikLundell commented 2 months ago

Sorry, I have no idea what might be going on. The only thing I've done is to try to make the buggers show up when they're supposed to (and disappear when the rest of the tree does), but I have no idea what effects they may have beyond that.

If it is caused by treetops then rebug removing them with map editing should make a difference. I'd also try to wait first and sleep afterwards (to catch the case when whatever is causing it goes away with time). I might also try adjusting the time to night time with a heavy cloud cover to make sure there is no light to shadow (although that doesn't guarantee the processing is skipped).

I'd also try to teleport away to sleep (again to catch the case where something with the character passes with time).

NetSysFire commented 2 months ago
PatrikLundell commented 2 months ago

Did you spawn the treetop as well, or only the base of it? I suspect the treetop doesn't spawn unless you causes the game to load submaps.

NetSysFire commented 2 months ago

It makes no difference whether or not a tree top is present.

PatrikLundell commented 2 months ago

I tried to hack trees to not specify any roofs, but it made no difference (in case there's some weird extra "should there be a roof here" stuff). However, I've encountered a new problem, namely that the game crashes (with the hack reverted), presumably during wildlife movement: Exception thrown at 0x00007FF70CFA3D99 in cataclysm-tiles.exe: 0xC0000005: Access violation reading location 0xFFFFFFFFFFFFFFFF.

cataclysm-tiles.exe!monster::move() Line 1164 C++ cataclysm-tiles.exe!`anonymous namespace'::monmove() Line 316 C++ cataclysm-tiles.exe!do_turn() Line 657 C++ cataclysm-tiles.exe!WinMain(HINSTANCE * formal, HINSTANCE * formal, char * formal, int formal) Line 868 C++

on line if( !here.inbounds( candidate ) ) { in monmove.cpp (line 1164 in the master downloaded a short while ago), but I can't figure out what the erroneous pointer is supposed to be. Destination is (106, 25, 0), and so within the bubble, and distance_to_target is 2.0, so pos() should also be in range, as should all candidate positions fed to inbounds. here looks like a normal map to me.

PatrikLundell commented 2 months ago

/confirmed

I can see what you're reporting, but have no idea what's causing it. I've recompiled in debug mode, causing everything to be even more glacial, but fail to repeat and catch the crash.

IdleSol commented 2 months ago

A few fun facts. To test it out, I found a lonely standing tree.

  1. Slowdown occurs on the tiles adjacent to the tree. They are marked with a target in the picture.

test 1

  1. On the other tiles, there is no slowdown (or not noticeable).

Note. Character position for further testing

test 2

  1. I saved and loaded the slowdown remains.
  2. I turned off the game and restarted. The slowdown remains.
  3. I cut down a tree. The slowdown remains.

test 3

  1. But the area where the slowdown manifests itself has changed.

test 4 Unmarked, but on the trunk and stump, the slowdown is there too.

  1. I repeated the steps with save and load, to rule out some variations. The slowdown remains in the same tiles.

  2. I started chopping the trunk and stump, into logs. The slowdown was disappearing from the neighboring tiles.

test 5 test 6

  1. When I chopped the last part into logs, the slowdown disappeared.

  2. To test it, using the debug menu, I created a new tree trunk on the ground. The slowdown appeared. https://github.com/CleverRaven/Cataclysm-DDA/blob/d6a507f7f318e67b89699fe6827175424f6e7a20/data/json/furniture_and_terrain/terrain-flora.json#L2603

  3. Modified the file by removing all flags. This has no effect whatsoever.

No other ideas. Except for the idea of hooking someone up to see what process is causing the game to slow down.

IdleSol commented 2 months ago

I found the parameter that's causing the slowdown. It's all about coverage. On a tree trunk, it's 45. https://github.com/CleverRaven/Cataclysm-DDA/blob/d6a507f7f318e67b89699fe6827175424f6e7a20/data/json/furniture_and_terrain/terrain-flora.json#L2609

Change it to 0 and compare the speed when you try to sleep.

At 10, there's already a noticeable slowdown. 100 and 45, in my opinion, are no different. I haven't really measured it accurately.

So I think the reason for this is the coverage parameter. More precisely, in the interaction between this parameter and the function responsible for sleep. But we need someone who can check this and tell us more precisely.

UPD.

Some changes. If you try to fall asleep on a tree trunk, there is no slowdown. Provided there are no other items with coverage greater than 0 nearby.

If you teleport into a tree, there will be slowdown. But because the game forcibly moves you to a neighboring square. Surround the tree with walls and you can sleep without slowdown.

Surround the tree with walls and leave one free tile. And you can sleep on it without slowdown. test 7

Or place a tree trunk in the house. Similar. There is no slowdown.

The bed has a 40% cover. But it has no effect on speed. As long as you don't take the bed outside.

fairyarmadillo commented 2 months ago

Cover has some functionality in lightmap.cpp and it's possible that the issue is there. Building the vision cache is really resource intensive.

IdleSol commented 2 months ago

And you probably answered correctly.

https://github.com/CleverRaven/Cataclysm-DDA/blob/35073a9c5e00f9c1b2f855ce933b06ff203c93b9/src/lightmap.cpp#L194

I was paying attention to that condition: https://github.com/CleverRaven/Cataclysm-DDA/blob/35073a9c5e00f9c1b2f855ce933b06ff203c93b9/src/lightmap.cpp#L220

So I went to a tree, sat down and waited for 5 minutes. Which resulted in a similar slowdown of the game. If the character is standing, this condition is ignored.

RenechCDDA commented 2 months ago

Well this is weird. The function name implies we're always rebuilding the cache, but we're... only sometimes?

In any case, this SHOULD be perfectly safe. And I can confirm that it eliminates this performance issue entirely:

index bbe88a5b40..f73b3fc18d 100644
--- a/src/lightmap.cpp
+++ b/src/lightmap.cpp
@@ -219,8 +219,10 @@ bool map::build_vision_transparency_cache( const int zlev )
             vision_transparency_cache[p.x][p.y] = LIGHT_TRANSPARENCY_OPEN_AIR;
         } else if( ( is_crouching || is_prone || low_profile ) && coverage( loc ) >= 30 ) {
             // If we're crouching or prone behind an obstacle, we can't see past it.
-            vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
-            dirty = true;
+            if( vision_transparency_cache[loc.x][loc.y] != LIGHT_TRANSPARENCY_SOLID ) {
+                vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
+                dirty = true;
+            }
         }
     }
IdleSol commented 2 months ago

Is the problem exactly in this function? Maybe I misunderstood something.

As I understand it:

  1. The character's position is taken
  2. LIGHT_TRANSPARENCY_OPEN_AIR is set for the tile the character is standing on
  3. For tiles in radius 1, the transparency cache is updated and LIGHT_TRANSPARENCY_SOLID is set if the conditions are met.

In the tree example, only for one tile the vision_transparency_cache parameter is updated. And it doesn't explain why it doesn't happen in a house. Or if you surround the tree with walls.

Perhaps we should look at a function that uses this value?

RenechCDDA commented 2 months ago

It sets the seen_cache as dirty every turn:

https://github.com/CleverRaven/Cataclysm-DDA/blob/6a8d75a468eba3084a616bf3ec700c6e78753c48/src/map.cpp#L9560-L9562

Which then triggers the rebuild of the seen cache. which is the entirety of the hot path during profiling:

https://github.com/CleverRaven/Cataclysm-DDA/blob/6a8d75a468eba3084a616bf3ec700c6e78753c48/src/map.cpp#L9580-L9582

I don't see any reason to set the cache as dirty if the cache does not change.

Notably the seen cache is already being properly dirtied if the player moved or their vision range changed.

https://github.com/CleverRaven/Cataclysm-DDA/blob/6a8d75a468eba3084a616bf3ec700c6e78753c48/src/map.cpp#L9579

So the code I'm suggesting changing is explicitly resetting the cache every turn even when the situation doesn't change. Actually, we can be even safer here by rebuilding the cache if movemode changes

index bbe88a5b40..7e5d283ff6 100644
--- a/src/lightmap.cpp
+++ b/src/lightmap.cpp
@@ -212,6 +212,7 @@ bool map::build_vision_transparency_cache( const int zlev )
     bool low_profile = player_character.has_effect( effect_quadruped_full ) &&
                        player_character.is_running();
     bool is_prone = player_character.is_prone();
+    static move_mode_id previous_move_mode = player_character.current_movement_mode();

     for( const tripoint &loc : points_in_radius( p, 1 ) ) {
         if( loc == p ) {
@@ -219,8 +220,11 @@ bool map::build_vision_transparency_cache( const int zlev )
             vision_transparency_cache[p.x][p.y] = LIGHT_TRANSPARENCY_OPEN_AIR;
         } else if( ( is_crouching || is_prone || low_profile ) && coverage( loc ) >= 30 ) {
             // If we're crouching or prone behind an obstacle, we can't see past it.
-            vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
-            dirty = true;
+            if( vision_transparency_cache[loc.x][loc.y] != LIGHT_TRANSPARENCY_SOLID ||
+                previous_move_mode != player_character.current_movement_mode() ) {
+                vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
+                dirty = true;
+            }
         }
     }
GuardianDll commented 2 months ago

i am still not very familiar to what happens here, but i tested the last suggestion, and what i spot is that it doesn't help to solve the bug in any way, comparing to the first diff image

Brambor commented 1 month ago

What about crafting? When a flashlight (the only source of light in a dark room) runs out of batteries the character should no longer be able to see to continue crafting. Will the character stop crafting with these changes?

IdleSol commented 1 month ago 
bool map::build_vision_transparency_cache( const int zlev )
...
    static move_mode_id previous_move_mode = player_character.current_movement_mode();

    for( const tripoint &loc : points_in_radius( p, 1 ) ) {
        if( loc == p ) { 
            vision_transparency_cache[p.x][p.y] = LIGHT_TRANSPARENCY_OPEN_AIR;
        }
        else if( ( is_crouching || is_prone || low_profile ) && coverage( loc ) >= 30 ) {
            if( vision_transparency_cache[loc.x][loc.y] != LIGHT_TRANSPARENCY_SOLID ||
                previous_move_mode != player_character.current_movement_mode() ) {
                    vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
                    dirty = true;
            }
        }
    }
    return dirty;
}

I'm sure I'm misunderstanding something. But doesn't it look like the following?

Some_function
...
    X = A

    for i=1 to 9 do
        if i = 5 then  
            vision_transparency_cache[p.x][p.y] = LIGHT_TRANSPARENCY_OPEN_AIR;
        else if ( Some_condition ) then 
            if X != A then 
                vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
                dirty = true;
            end
        end
    end
    return dirty;
end

I'm confused about a few things, but the main one is:

    X = A
    if X != A then

This condition is always false.

Other things:

  1. Is the cycle definitely doing 9 turns? It doesn't go to infinity, does it?
  2. Do we need to check the loc == p condition at each cycle turn? Can it be moved outside the cycle?
  3. Do we need to check the previous_move_mode != player_character.current_movement_mode() condition at every cycle turn?

As far as I understand, the character cannot change its movement mode during the execution of this function.

RenechCDDA commented 1 month ago

I'm confused about a few things, but the main one is:

https://en.cppreference.com/w/cpp/language/static

Basically the value held inside the static variable is retained for next time the function is run.

Is the cycle definitely doing 9 turns? It doesn't go to infinity, does it?

The specific for loop I suggested modifying only does the 9 squares around the player's XY coordinates, on the z-level it was called for. However the call to map::build_vision_transparency_cache calls it across all z-levels, sequentially. It only checks valid z-levels.

Do we need to check the previous_move_mode != player_character.current_movement_mode() condition at every cycle turn?

C++ operator precedence means that it can return early. It is an extraordinarily cheap check compared to rebuilding the entire vision cache, so regardless... yeah.

RenechCDDA commented 1 month ago

Basically the value held inside the static variable is retained for next time the function is run.

Oh and that's why it doesn't work in Guardian's testing lol, it needs another assignment or else it's stuck on the very first value it picks up forever.

IdleSol commented 1 month ago

I still continue to not understand.

https://github.com/CleverRaven/Cataclysm-DDA/blob/6a8d75a468eba3084a616bf3ec700c6e78753c48/src/map.cpp#L9560-L9562

Some_function
    for i=1 to 21 do
        Some_cache_access_operations
        if i != p.z then  
            return false
        else
            for i=1 to 9 do
                if i = 5 then  
                    vision_transparency_cache[p.x][p.y] = LIGHT_TRANSPARENCY_OPEN_AIR;
                else if ( Some_condition ) then 
                    if X != A then 
                        vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
                        dirty = true;
                    end
                end
            end
            return dirty;
        end
    end
end
GuardianDll commented 1 month ago

should #73590 be modified, to use the second suggestion (if someone update it to contain assignment?), or the first one is okay? found the comment in 73590, will do

NetSysFire commented 1 month ago

I updated and tried again, but it is still super slow when using the provided save and sleeping in the improvised shelter.

gdb says this about it:

Thread 1 (Thread 0x7ffff748f7c0 (LWP 1097349) "cataclysm-tiles"):
#0  0x00007ffff793f958 in __sqrt_finite () from /usr/lib/libm.so.6
No symbol table info available.
#1  0x0000555555e8f3a3 in trig_dist () at src/line.h:159
No locals.
#2  rl_dist () at src/line.h:184
No locals.
#3  0x0000555556b4b0e1 in cast_horizontal_zlight_segment<0, 1, 1, 0, 1, float, &(sight_calc(float const&, float const&, int const&)), &(sight_check(float const&, float const&)), &(accumulate_transparency(float const&, float const&, int const&))> () at src/shadowcasting.cpp:298
No locals.
#4  0x0000555556b4f7de in cast_zlight<float, &(sight_calc(float const&, float const&, int const&)), &(sight_check(float const&, float const&)), &(accumulate_transparency(float const&, float const&, int const&))> () at src/shadowcasting.cpp:603
No locals.
#5  0x000055555656d439 in map::build_seen_cache () at src/lightmap.cpp:1040
No locals.
#6  0x00005555565e4271 in map::build_map_cache () at src/map.cpp:9596
No locals.
#7  0x00005555561d658b in do_turn () at src/do_turn.cpp:655
No locals.
#8  0x0000555555cd1ea9 in main () at src/main.cpp:868
No locals.

I tried a couple of times and it appears to happen in cast_horizontal_zlight_segment

NetSysFire commented 1 month ago

perf.data.gz

I was advised to use --call-graph=lbr but I am getting cycles:Pu: PMU Hardware or event type doesn't support branch stack sampling., so I just used perf record -F 99 -g

Edit: We also determined that sleeping next to an underbrush (does not matter if harvested or not) reproduces the bug. Probably coverage related.

RenechCDDA commented 1 month ago

The new GDB is spot on, also reproducible on windows. Only problem is... I have no idea what's going on here.

image

RenechCDDA commented 1 month ago

Okay, I see the problem. Vision_transparency_cache is a copy of transparency_cache. Rather obvious when you read the declaration comments, silly Renech.

We copy it(always), (then when dirty) we update our copy, but the original is still different. Everytime we go through map::build_vision_transparency_cache we copy out of the original again, and compare our new copy to the original. Oops, there is once again a difference to what it should be. Dirty the vision transparency cache, pass it along. Next time it gets called we copy the original again and - surprise, our modifications don't exist because we're looking at the original.

Here's an example of what I mean, this runs blazing fast (for real this time, hopefully!):

index f03e6da993..56a9f882de 100644
--- a/src/lightmap.cpp
+++ b/src/lightmap.cpp
@@ -223,6 +223,7 @@ bool map::build_vision_transparency_cache( const int zlev )
             if( vision_transparency_cache[loc.x][loc.y] != LIGHT_TRANSPARENCY_SOLID ||
                 previous_move_mode != player_character.current_movement_mode() ) {
                 previous_move_mode = player_character.current_movement_mode();
+                transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID; // update transparency cache itself
                 vision_transparency_cache[loc.x][loc.y] = LIGHT_TRANSPARENCY_SOLID;
                 dirty = true;
             }

That said I am not even vaguely sure this is safe, good practice, or anything! Please don't PR this unless you are confident in it.

fairyarmadillo commented 1 month ago

I had help from @andrei8l when I messed with vision, perhaps they can weigh in (sorry for the ping if not!), as they seem to know their stuff.