Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Android Editor: Any filesystem operation (moving, creating files) trigger a full reimport after #84974 due to bad tracking of .import modified time #94416

Open
Saul2022 opened this issue Jul 16, 2024 · 31 comments

Comments

@Saul2022
Copy link

Saul2022 commented Jul 16, 2024

Tested versions

Reproducible in godot 4.3 beta 3

System information

Sansung galaxy s23+

Issue description

While it sure the android editor is not made for big project with more than 300mb or 500 , it kind of weird than in the tps demo it takes just a minute to remove 1 file , meanwhile when going on play mode save all scenes doesn't take nearly as much , so that 's why i think this might be more or less a bug.

In other instance in the pc version in a igpu( rx vega 3) it works way faster to load the project or doing the same adjustments despite being 4 times slower than the s23 and even in vulkan the s23 is faster despite the drivers ineficences.

Prob partial fix
#93064 ?

Edit: testing it last artifact and it doesn't make much difference in performanxe when removing a resource or loading the scene

Steps to reproduce

Open a big project like the mrp of the tps demo modifed https://github.com/godotengine/tps-demo

Load the scene or try to remove files to notice the massive slowdown.

Minimal reproduction project (MRP)

"N/A" ( Too big for mrp, download the tps demo link) https://github.com/godotengine/tps-demo )

@Calinou
Copy link
Member

Calinou commented Jul 16, 2024

I wonder if this is due to Android scoped storage bottlenecking I/O performance somehow. Unfortunately, there's no way to opt out of this in Android 11 or later.

@Saul2022
Copy link
Author

Saul2022 commented Jul 16, 2024

I wonder if this is due to Android scoped storage bottlenecking I/O performance somehow.

Idk, what i think could happen is that the android editor might be reloading the scene every time you want to acces it storage or when you go from one window unrelated to the editor , and then back to the editor , as it loading it similar to when you want to load your project.

It a really weird case noticeable on big project with all scripts. Shaders etc, because , for example in the sun temple modified project, it not taking as long as the tps or my project. You can reproduce it in your sansung tab 9 ultra?

Edit the remove file slowdown is clear to be android fault even on an igpu removing files is instant( at the cost of making my pc black screen. Again..)

@Calinou
Copy link
Member

Calinou commented Jul 16, 2024

I can reproduce this on the Truck Town demo on 4.3.beta 92c8e87 (Android 14, Samsung Galaxy Tab S9 Ultra). Renaming or moving a single file takes 3+ seconds despite that demo only have a few dozen files. Doing this on my desktop PC takes about 300 milliseconds in comparison. While my PC is a good deal faster than this tablet, I'd expect the operation to take less than 1 second on the tablet.

Deleting a file (such as a newly duplicated image that isn't used in any scene) doesn't seem to take any significant amount of time though.

I don't have access to devices that run Android versions older than 11 to check if this is related to scoped storage.

@Saul2022
Copy link
Author

Saul2022 commented Jul 17, 2024

Deleting a file (such as a newly duplicated image that isn't used in any scene) doesn't seem to take any significant amount of time though.

Weird, have you tried on the tps demo? I think for removing files, that were the most noticeable speed slowness happens as it way bigger than the truck demo( way more files) , trying on the igpu in the past was instant (1 sec). Same goes when you go from another window, and get back at the godot one, going from play to editor mode or duplicating a file.

Deleting a file (such as a newly duplicated image that isn't used in any scene) doesn't seem to take any significant amount of time though.

Weird tho , i can't reproduce the slowness of renaming files( it slow, but it just 2-3 seconds renaming a folder on the tps demo)

@Saul2022
Copy link
Author

Saul2022 commented Jul 18, 2024

I think i could figure out the problem testing this pr that fixes the window making it possible to see the reimporting window when loading and kinda when removing files, which what i feel it does is reload all the entire project just to remove something, which would explain why i get the same errors when loading the project as the ones from removing an file,sadly cant drag the window while on progress but we can have an idea of why this happens

Screenshot_20240718_031502

And when loading the project

Screenshot_20240718_032126

As seen one is saving and importing, while the other is reimporting everything and importing scenes So fpr removing or load , it seems it might loose the reference of the file or locating the exact files and trying to recover by reloading the project? . As for loading the project i don't get why it has to reimport all models but i guess that up to other issue.

Alzo screenshot when it goes from other window to back to the godot one
Screenshot_20240718_033611

@Hilderin
Copy link
Contributor

I don't have access to an Android to test it, but from what I see, my guess is that FileAccess::get_modified_time returns a different value even if the files are not updated or maybe the date is not perfect if read just after the file is written on disk. I saw that the storage was upgraded for Android in beta 3 and a PR merged that adds a new check on the date of the .import file when scanning the project.

@akien-mga
Copy link
Member

CC @m4gr3d @KoBeWi

@akien-mga
Copy link
Member

I saw that the storage was upgraded for Android in beta 3 and a PR merged that adds a new check on the date of the .import file when scanning the project.

To confirm that hypothesis, could someone affected test earlier beta snapshots to see if this is indeed a regression in beta 3?

@akien-mga akien-mga added this to the 4.3 milestone Jul 18, 2024
@Saul2022
Copy link
Author

To confirm that hypothesis, could someone affected test earlier beta snapshots to see if this is indeed a regression in beta 3?

Testing on the tps demo modifed project( lurked from the forge final collaboration pr tests,. Take into account seconds may vary a bit as it not accurate enough, because i am just using the watch cronometer without a tool script)

On 4.3 beta 3 it takes 1 minute 20 seconds

On 4.3 beta 1 it takes 16 seconds and removing files is instant this time without the whole project reloading itself

Then to test if regression was between beta 2 it takes just like beta 1 17 seconds.

So it seems's this is a regression, in my opinion it more on the side of reimporting assets than scanning, as reimport is clearly what takes the most time here.

@Hilderin
Copy link
Contributor

So it seems's this is a regression, in my opinion it more on the side of reimporting assets than scanning, as reimport is clearly what takes the most time here.

I was suggesting scanning because reimport assets should not occur at all when opening a project, renaming files or returning to the editor after going to another window, if no changes are made on the disk. But seriously, without debugging, I can be in the absolute wrong!!

@Saul2022
Copy link
Author

Saul2022 commented Jul 18, 2024

But seriously, without debugging, I can be in the absolute wrong!!

It understandable, debugging on android is way harder than pc ( where even trying to put the error logs actions is hard, because the format is aabb instead of apk ) Sadly it seems reimporting is still happening on 4.3 beta 3 based mainly on the m4gr3d exporting pr that fixes the loading import screen in android which allows to show that the main slowdown despite no changes are made in project files.

Edit in case it wasn't android exclusive i tried the hilderin filesystem dock pr, and it works well there( no reimporting file, just reopening the scene after scanning the project files. )
#93526

@Saul2022
Copy link
Author

This is getting real weird here, like after i installed 4.3 beta 2 and 1 and then after doing the test there and turning on beta 3 project, now it has the same loading speed and the slowdown on removing files is gone.

I have a theory that this might have happened : because these project were first opened in 4.3 beta 3( which looks to be the faulty one as beta 1 and 2 never seemed to run on this), they were fixed when they were transfered to the older versions which might explain why when transfering it back to beta 3 it fixed.

So here's the what we can do

Install a zip largue project ( for example the tps demo one) and extract it. Also keep the zip folder

Procced to install godot 4.3 beta 3 and launch the project, ( notice how slow is it as it reimporting the entire project)

Now uninstall godot 4.3 beta 3( to allow the older version to be installed) and delete the extracted project( as if we used this one in the older beta it will be fixed when going back to beta 3)

Then install beta 2 or 1, launch it, quit, and then extract the project to import it into these versions( notice how when it loads it goes much faster and theres no slowdown when removing filws).

Sorry if this is confusing i try what i can and
this bug is kind of rare to reproduce

@Hilderin
Copy link
Contributor

Wow, this is a very intriguing turn of event!!

I finally was able to test on my Samsung A14 on Android 14. I tested the TPS demo project and unfortunately, I was not able to reproduce the long project loading and rescanning when removing a file or opening a scene.

I used a custom build from master.

@Saul2022
Copy link
Author

Saul2022 commented Jul 22, 2024

I used a custom build from master.

Interesting , what custom build did you use ? You got any artifact from it?

Edit: Using an artifact from the last merge( this one https://github.com/godotengine/godot/actions/runs/10022669772 ) and still able to reproduce this problem on the project i mentioned.

Video for proof( file size too big).

https://drive.google.com/file/d/1FpnbU_I_A8lFnTvLI568sd1iONncOAKR/view

@Hilderin
Copy link
Contributor

Hilderin commented Jul 22, 2024

Interesting , what custom build did you use ? You got any artifact from it?
I build locally from master with scons platform=android arch=arm64 production=yes target=editor

I just tested on my device using this artefact: https://github.com/godotengine/godot/actions/runs/10022669772

Maybe I do something wrong to reproduce the problem.

This is what I did:

  • Remove Hodot
  • Deleted the tps folder
  • Download TPS from https://godotengine.org/asset-library/asset/2710 on my computer
  • Unzip TPS on my computer
  • Upload the tps demo folder to my android device via Android Studio (on SD card)
  • Launch Godot
  • Import the tps demo folder
  • Wait a couple minutes to let Godot reimport everything (this is normal that the first time it's long because the .godot folder is not there)
  • Try to close Godot et reopen the project, it's super fast
  • Try to rename level.tscn to level2.tscn, it's super fast
  • Try to rename a node in level.tscn (it took 10-15 sec, I'm on a low spec phone, I guess it could be normal)

But... then I tried to start the game... it worked, but, when I closed it and got back to Godot, it took a couple of minutes with a file system rescan and a black screen, exactly as the first load.

I'll try to add more print log later and do more testing now that I'm able to reproduce the problem.

@Hilderin
Copy link
Contributor

After much testing, I'm really not able to reproduce the original problemof this issue on my device, even if I use the artefact https://github.com/godotengine/godot/actions/runs/10022669772.

I thought I was able to reproduce the problem, but it was only the fact that when the running game is closed, Godot is completely restarted and opening the scene from TPS demo takes around 15 seconds on my device. I don't known if it's normal that Godot must be restarted at each start/stop of the game? I never had the problem where files are being reimported even if not modified.

The other thing I find strange is the fact that scanning the project takes around 3 seconds which is not that fast considering that the project contains only 588 files.

Sorry, maybe someone else will have more luck or maybe it's a problem on some device only.

@Saul2022
Copy link
Author

when the running game is closed, Godot is completely restarted and opening the scene from TPS demo takes around 15 seconds on my device. I don't known if it's normal that Godot must be restarted at each start/stop of the game? I never had the problem where files are being reimported even if not modified.

Weird that the only part where you can reproduce this too( i have the same problem when you leave the edutor window or run and then quit the game,which doesn't happen in beta 2 and 1 and it took me minutes for the project to load after that)

The other thing I find strange is the fact that scanning the project takes around 3 seconds which is not that fast considering that the project contains only 588 files.

Well the device is not that slow, though for me and my s23+ it takes more , and that kind of similar to my time rescanning in pc.

Sorry, maybe someone else will have more luck or maybe it's a problem on some device only.

It's ok, it can be more or less workarounded by doing what i said , but it pretty annoying and more if new people run into this stuff..though i didn'rt really mean about renaming files, just when you remove them from file system which is when editor redraws itself

Also about the android studio thing , what do you meanv by that? Did you install something or moved from file manager?

@akien-mga
Copy link
Member

So I did some testing and I can reproduce the issue in 4.3.beta3 and latest master with a custom build.

The symptoms I see are that any filesystem operation triggers a rescan (that's expected, or at least not a new issue - #50576), but since 4.3.beta3 that rescan takes much longer (like a minute), or seems to be stuck at around 100% for a long time.

I saw that the storage was upgraded for Android in beta 3 and a PR merged that adds a new check on the date of the .import file when scanning the project.

To confirm that hypothesis, could someone affected test earlier beta snapshots to see if this is indeed a regression in beta 3?

I confirmed that hypothesis. @Hilderin was referring to #84974, and indeed reverting that PR fixes the issue. After the revert, there is still a rescan on any operation, but it takes 2-3s.

Now, that's a bit surprising as #84974 should be triggering reimports, not just rescans. I wonder if on the Android editor imports are "hidden" and bundled in the FS dock rescan, at least visually?

@akien-mga
Copy link
Member

Now, that's a bit surprising as #84974 should be triggering reimports, not just rescans. I wonder if on the Android editor imports are "hidden" and bundled in the FS dock rescan, at least visually?

So that was indeed the case, the ProgressDialog was not rendering on Android specifically. #94662 will fix that.

So the problem is indeed caused by a reimport of project assets after the (expected) rescan of all the project. Importing assets in a big project like the TPS demo takes a long time, but the fact that it wants to reimport after any simple operation like creating a folder is indeed a bug caused by #84974.

This is getting real weird here, like after i installed 4.3 beta 2 and 1 and then after doing the test there and turning on beta 3 project, now it has the same loading speed and the slowdown on removing files is gone.

So I experienced the same too, which confused me initially, but my hypothesis is that 4.3 beta 2 and 4.3 beta 3 generate something different in the .godot folder when importing. When opening a project in 4.3 beta 2, all files are properly imported, and then after opening the project in 4.3 beta 3, the pre-existing .godot folder with imported files prevent the bug from happening.

Deleting the .godot folder should cause the issue again in 4.3 beta 3, even if you used beta 2 in the meantime.

I haven't yet had time to try it out (might do tomorrow), but my next debugging idea was to open the project in 4.3 beta 2, copy the .godot folder to my desktop, delete it on Android, open the project again in 4.3 beta 3, copy the .godot folder to my desktop, and diff both folders to see if there's a difference.

@KoBeWi
Copy link
Member

KoBeWi commented Jul 23, 2024

the fact that it wants to reimport after any simple operation like creating a folder is indeed a bug caused by #84974.

No, it's another bug that surfaced because of this PR. Creating a folder does not change .import files.
Either it does change them on Android or the cached import modified time is wrong.

@akien-mga
Copy link
Member

Either it does change them on Android or the cached import modified time is wrong.

I think it's the latter. It's not just creating a folder that triggers this issue, but also simply closing Godot and reopening it.
As in, anything that triggers as fs scan will do a full reimport.

So either the cached import modified time is wrong, or the modified time for the .import files is wrongly calculated (or both use different and incompatible methods?).

@akien-mga
Copy link
Member

akien-mga commented Jul 23, 2024

BTW the TPS demo is really overkill for testing this bug, it's reproducible also with smaller projects. I suggest Kenney's 3D platformer starter kit from the AssetLib (with #94662 to make the progress dialog visible).

@Saul2022
Copy link
Author

Saul2022 commented Jul 23, 2024

So either the cached import modified time is wrong, or the modified time for the .import files is wrongly calculated (or both use different and incompatible methods?).

I would say it more that the project itself is not taking into account the .godot folder and it might just think that we are importing a new project, as the only thing that seems faster after project reloading are the files scans.

Edit: Interestingly enough ,though this is for a different issue, after testing #94662 i noticed that in the project manager when you want to import a project you can't browse anything and this what you see on screen, where i can only see the tps folder that i examined to open the project. Though this is not rekated to this pr as it noticeable in older artifact like the one you last merged 2/3 days ago

Screenshot_20240723_183204

@Hilderin
Copy link
Contributor

Interestingly enough ,though this is for a different issue, after testing #94662 i noticed that in the project manager when you want to import a project you can't browse anything and this what you see on screen

I already created an issue for that: #94570

@akien-mga
Copy link
Member

Added some prints and confirmed that the cached import modified time is wrong:

diff --git a/editor/editor_file_system.cpp b/editor/editor_file_system.cpp
index 0b2cf1424b..44b4a8dad8 100644
--- a/editor/editor_file_system.cpp
+++ b/editor/editor_file_system.cpp
@@ -722,8 +722,11 @@ bool EditorFileSystem::_update_scan_actions() {
 				String full_path = ia.dir->get_file_path(idx);
 
 				bool need_reimport = _test_for_reimport(full_path, false);
+				print_line(vformat("*** TEST REIMPORT ***: _test_for_reimport: %s", need_reimport ? "true" : "false"));
 				if (!need_reimport && FileAccess::exists(full_path + ".import")) {
 					uint64_t import_mt = ia.dir->get_file_import_modified_time(idx);
+					print_line(vformat("*** TEST REIMPORT ***: get_file_import_modified_time: %d", import_mt));
+					print_line(vformat("*** TEST REIMPORT ***: FileAccess::get_modified_time: %d", FileAccess::get_modified_time(full_path + ".import")));
 					if (import_mt != FileAccess::get_modified_time(full_path + ".import")) {
 						need_reimport = true;
 					}
07-24 10:30:57.380 21724 21764 I godot   : *** TEST REIMPORT ***: _test_for_reimport: false
07-24 10:30:57.381 21724 21764 I godot   : *** TEST REIMPORT ***: get_file_import_modified_time: 0
07-24 10:30:57.382 21724 21764 I godot   : *** TEST REIMPORT ***: FileAccess::get_modified_time: 1721307254

@akien-mga
Copy link
Member

I made a proper MRP with a single glb file, so it's easier to test and compare the effect of different builds:
testreimportbug.zip

I haven't yet had time to try it out (might do tomorrow), but my next debugging idea was to open the project in 4.3 beta 2, copy the .godot folder to my desktop, delete it on Android, open the project again in 4.3 beta 3, copy the .godot folder to my desktop, and diff both folders to see if there's a difference.

I did that with the above MRP, but didn't find anything conclusive in the differences of the .godot folder. Both the build with the bug and a build with the regression reverted seem to properly populate .godot/editor/filesystem_cache8 with modified times.

I can still reproduce the fact that:

So "fixing" the bug by opening it with a reverted build doesn't seem to be tied to the contents of files in .godot, but something else. Some hypothesis:

  • Editor cache outside the project folder (thumbnails, etc.)
  • Actual file modification dates for the files in the folder

I don't have time to keep poking at this myself, so I'd appreciate help from folks familiar with EditorFileSystem (@KoBeWi, @Hilderin) and/or debugging Android-specific issues (@m4gr3d). In particular I don't know if it's possible to step through the editor code from Android Studio, but that could help understand why the import times are 0 at this step.

For 4.3.rc1, I will just #ifndef ANDROID_ENABLED the code that reimports when the import time is a mismatch.

akien-mga added a commit to akien-mga/godot that referenced this issue Jul 24, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
@akien-mga
Copy link
Member

akien-mga commented Jul 24, 2024

For 4.3.rc1, I will just #ifndef ANDROID_ENABLED the code that reimports when the import time is a mismatch.

I've done that with #94691, so this is no longer a release blocker IMO.

To anyone who wants to further debug this issue and attempt to fix it, you'd have to revert #94691 to see the bug again.

@akien-mga akien-mga modified the milestones: 4.3, 4.4 Jul 24, 2024
@akien-mga akien-mga changed the title Project takes too long to load or remove files in the Android Editor Android Editor: Any filesystem operation (moving, creating files) trigger a full reimport after #84974 due to bad tracking of .import modified time Jul 24, 2024
Borges-IST-2003 pushed a commit to Borges-IST-2003/godot that referenced this issue Jul 24, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
@Hilderin
Copy link
Contributor

Hilderin commented Jul 25, 2024

Thanks a lot @akien-mga for your tests and debug.

I'm still not able to reproduce the problem on my side so I created a draft PR #94717 if someone wants to use the artefact from the PR and test on their device and paste me the output logs, I would be able to better comprehend the problem and maybe find a solution.

Artefact: https://github.com/godotengine/godot/actions/runs/10087688942/artifacts/1737806253

Luis-Wong pushed a commit to Luis-Wong/godot that referenced this issue Jul 26, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
RadiantUwU pushed a commit to RadiantUwU/godot that referenced this issue Jul 27, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
kii-chan-reloaded pushed a commit to kii-chan-reloaded/godot that referenced this issue Aug 3, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
@m4gr3d
Copy link
Contributor

m4gr3d commented Aug 3, 2024

I debugged the logic flow and found out that FileAccessUnix::_get_modified_time(...) seems to alternate between different modified time values for the same file.
This causes the logic in EditorFileSystem::_process_file_system(...) to invalidate the file cache and reset the modified time causing the reimport.

For some reasons, the issue causing FileAccessUnix::_get_modified_time(...) to alternate between values seems to only occur on Android; I was unable to replicate that issue on a linux machine.

2nafish117 pushed a commit to 2nafish117/godot that referenced this issue Aug 5, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
chryan pushed a commit to chryan/godot that referenced this issue Aug 6, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
@Hilderin
Copy link
Contributor

@Saul2022
Can you try to see if #95678 fixes the problem where all the assets are reloaded each startup on your Android device. In this PR, I removed the code added in the commit 7acb61d that disabled the check on last modification date for .import file on Android.

@Saul2022
Copy link
Author

Saul2022 commented Aug 21, 2024

@Saul2022 Can you try to see if #95678 fixes the problem where all the assets are reloaded each startup on your Android device.

Yep tried on the latest artifact and it's gone and time is 1:22 minutes on startup and 13 on second , scanning being pretty fast etc..load being again just the tps scene not being cached, great improvement. Feel free to close this one when it gets merged.

Edit also this exact scan is the same on a project where i duplicated the tps demo until the project got to 2.40 gb of files ( almost 5 gb total counting .godot it took 7:10 minutes on first startup 1 reload 40 seconds and third time 13 seconds scanning, all with file scan load instantly except startup certainly.

maidopi-usagi pushed a commit to maidopi-usagi/godot that referenced this issue Sep 11, 2024
This is disabling the logic added in godotengine#84974 which caused godotengine#94416.
That issue still needs to be debugged further, but this works around
the regression and should have minimal usability impact on Android.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants