action_time Using WeiDU's "ACTION_TIME" vs ".DEBUG"

[Incrementis]

EDIT EDIT EDIT: The library is now available. More information can be found here!

Greetings to all,

I use WeiDU's ACTION_TIME functionality to test the process time of a custom written library.

The macro I called writes content into several files in the “./weidu_external/” folder.

The results are as follows so far:

Spoiler

        WeiDU Timings
unmarshal KEY                                    0.000
OUTER_INNER_PATCH_SAVE           0.000
ACTION_TIME                                     0.000
<<<<<<<<                                              0.000
load TLK                                              0.000
DEFINE_PATCH_FUNCTION             0.000
LAUNCH_ACTION_MACRO              0.000
DEFINE_ACTION_FUNCTION           0.000
OUTER_SPRINT                                 0.000
OUTER_SET                                        0.000
INCLUDE                                             0.000
DEFINE_DIMORPHIC_FUNCTION   0.000
BUT_ONLY                                          0.000
REINCLUDE                                        0.000
parsing .log files                                0.000
Parsing TP2 files                                0.000
OUTER_FOR                                        0.000
DEFINE_ACTION_MACRO               0.000
APPEND                                             0.000
OUTER_INNER_PATCH                    0.000
ACTION_IF                                        0.000
Resolving LABELs                           0.000
READ_*                                              0.000
loading files                                     0.000
Parsing TPA files                            0.000
DEFINE_PATCH_MACRO               0.000
stuff not covered elsewhere         0.000
COPY                                                0.000
unmarshal TLK                               0.000
process_patch2                             0.016
eval_pe                                            0.016
saving files                                      0.906
TOTAL                                             0.938

As we can see, the total time is 0.938 (seconds?!) for almost 2*5,000 entries, which is fine in my opinion. The problem occurs when I check the time with a stopwatch as it shows about 30 seconds.

I assume this is the case because WeiDU writes the individual steps into the specific ".DEBUG" file. In this case there are 30,077 entries in the debug file.

Here are my questions:

• Is it possible to get the process time when writing to the debug file?
• Is it possible to give/ask the user the option to enable or disable debugging so that installation time can be significantly reduced?

EDIT:

The terminal prints the following “Appending to files” multiple times, possibly as many times as files have been written to (10,000 times). I assume printing on the terminal is also very time consuming?!

Here comes a third question:

• Is it possible to prevent this message from being printed into the terminal?

I already tried SILENT but it didn't work, so I'm assuming it won't prevent WeiDU from outputting "immutable" prints to the terminal?!

EDIT EDIT:

A table with time measurement was created:

Spoiler

Time stopwatch	Number of Entries	Time .DEBUG
5.64 sec	1,000	0.078 sec
11.30 sec	2,000	0.172 sec
16.85 sec	3,000	0.250 sec
22.74 sec	4,000	0.703 sec
29.94 sec	5,000	0.766 sec
36.42 sec	6,000	0.938 sec
43.30 sec	7,000	1.969 sec
52.25 sec	8,000	1.438 sec
58.36 sec	9,000	2.766 sec
1 min 8.07 sec	10,000	3.688 sec
3 min 12.32 sec	20,000	16.016 sec

You can also find the table here:

https://github.com/Incrementis/Infinity-Engine-Modding-Wiki-Content-/wiki/External-Libraries

There is also a .DEBUG file attached to this comment, so you can now see what the .DEBUG file looks like for 1k elements.

Thank you for taking the time to read this comment!

SETUP-ARRAYTEST_1k.DEBUG

Edited October 10, 2023 by Incrementis
Library is available

[DavidW]

Are you sure you're timing only the running of the library? WEIDU does a bunch of other things before and after executing core content and that can mess with timing. I use ACTION_TIME a fair amount and hadn't noticed the discrepancy.

Try this (using a stopwatch to compare)

PRINT "Press a key to start."
ACTION_READLN whocares
ACTION_TIME your_timer BEGIN
	LAF your_custom_functions END
END
PRINT "...aaand we're done. Press a key to continue."

Other than that... well, my debug files are long, but 30,000 lines does seem kind of extreme (I can't recall if WEIDU writes to the debug file as it goes along rather than at the end; I have a nasty feeling it does). I've never come across this as a constraint; are you willing to share your library so I can have a look? (Though I'm about to travel, so no promises I'll have a chance.)

 

[Incrementis]

30 minutes ago, DavidW said:

Are you sure you're timing only the running of the library? WEIDU does a bunch of other things before and after executing core content and that can mess with timing. I use ACTION_TIME a fair amount and hadn't noticed the discrepancy.

Try this (using a stopwatch to compare)

PRINT "Press a key to start."
ACTION_READLN whocares
ACTION_TIME your_timer BEGIN
	LAF your_custom_functions END
END
PRINT "...aaand we're done. Press a key to continue."

Other than that... well, my debug files are long, but 30,000 lines does seem kind of extreme (I can't recall if WEIDU writes to the debug file as it goes along rather than at the end; I have a nasty feeling it does). I've never come across this as a constraint; are you willing to share your library so I can have a look? (Though I'm about to travel, so no promises I'll have a chance.)

 

Thank you for your reply!

Sharing the library is fine with me since I plan to upload it to GitHub sooner or later anyway.

You can find the uploaded file in this answer.

It contains the mod folder containing the tp2 file and the lib folder containing the file. The WeiDU version I use is 24900.

No pressure, take your time. Testing the library from my side will take a lot of time anyway it seems :).

 

arraytest.zip

[DavidW]

OK, I can reproduce both the very long running time and the mismatch between that and the observed time. (My install recorded about 11 seconds, but while I didn't time the run, it was clearly much less than that.)

The reason the code is running so long is that it does 12,000 APPEND_OUTERs, and APPEND is relatively slow on WEIDU; generally, operations where WEIDU writes to file are slow compared to operations where it's just calculating or manipulating strings. (Don't ask me why, exactly.) The responsible block (as you probably know) is 

	OUTER_FOR(index = 0; index < ~!_slotNumbers~; ++index) BEGIN	
		APPEND_OUTER ~./weidu_external/temp/arrays/!_%!_setArrayName%.tpa~ ~~~~~	"%%!_setArrayName%%index%%"~~~~~
		APPEND_OUTER ~./weidu_external/temp/arrays/!_patch%!_setArrayName%.tpa~ ~~~~~	"%%!_setArrayName%%index%%"~~~~~
	END

The way to get around this slowdown is to write the data to a string, and then APPEND_OUTER the string at the end:

	OUTER_SPRINT data1 ""
	OUTER_SPRINT data2 ""
	OUTER_FOR(index = 0; index < ~!_slotNumbers~; ++index) BEGIN	
			OUTER_SPRINT data1 ~%data1%	"%%!_setArrayName%%index%%"%WNL%~
			OUTER_SPRINT data2 ~%data2%	"%%!_setArrayName%%index%%"%WNL%~ 
	END
	APPEND_OUTER ~./weidu_external/temp/arrays/!_%!_setArrayName%.tpa~ ~%data1%~
	APPEND_OUTER ~./weidu_external/temp/arrays/!_patch%!_setArrayName%.tpa~ ~%data2%~

The benchmark runs pretty much instantly on my computer with that tweak. (Since it's a macro, you should also put LOCAL_SPRINT data1 "" LOCAL_SPRINT data2 "" at the start of the macro if you do this; you should probably have LOCAL_SET index=0 too, come to think of it.)

[Incrementis]

1 hour ago, DavidW said:

OK, I can reproduce both the very long running time and the mismatch between that and the observed time. (My install recorded about 11 seconds, but while I didn't time the run, it was clearly much less than that.)

The reason the code is running so long is that it does 12,000 APPEND_OUTERs, and APPEND is relatively slow on WEIDU; generally, operations where WEIDU writes to file are slow compared to operations where it's just calculating or manipulating strings. (Don't ask me why, exactly.) The responsible block (as you probably know) is 

	OUTER_FOR(index = 0; index < ~!_slotNumbers~; ++index) BEGIN	
		APPEND_OUTER ~./weidu_external/temp/arrays/!_%!_setArrayName%.tpa~ ~~~~~	"%%!_setArrayName%%index%%"~~~~~
		APPEND_OUTER ~./weidu_external/temp/arrays/!_patch%!_setArrayName%.tpa~ ~~~~~	"%%!_setArrayName%%index%%"~~~~~
	END

The way to get around this slowdown is to write the data to a string, and then APPEND_OUTER the string at the end:

	OUTER_SPRINT data1 ""
	OUTER_SPRINT data2 ""
	OUTER_FOR(index = 0; index < ~!_slotNumbers~; ++index) BEGIN	
			OUTER_SPRINT data1 ~%data1%	"%%!_setArrayName%%index%%"%WNL%~
			OUTER_SPRINT data2 ~%data2%	"%%!_setArrayName%%index%%"%WNL%~ 
	END
	APPEND_OUTER ~./weidu_external/temp/arrays/!_%!_setArrayName%.tpa~ ~%data1%~
	APPEND_OUTER ~./weidu_external/temp/arrays/!_patch%!_setArrayName%.tpa~ ~%data2%~

The benchmark runs pretty much instantly on my computer with that tweak. (Since it's a macro, you should also put LOCAL_SPRINT data1 "" LOCAL_SPRINT data2 "" at the start of the macro if you do this; you should probably have LOCAL_SET index=0 too, come to think of it.)

Thank you, great solution!

I tested the code snippet from you and of course it makes much more sense to only call APPEND_OUTER twice by calling it outside the loop!

I understand that "%WNL%" is a WeiDU constant for Windows(?!) New Line. I couldn't find it in the WeiDU documentation.

Would you mind letting us(everyone who reads this post, as I am actually only one person) know where to find this?

Also, great catch about "index". I would have completely missed it since I only use it in loops.

I'll be sure to add you to the thanks section and add a link to this thread so everyone can see your post when I upload the library to GitHub!

[DavidW]

11 minutes ago, Incrementis said:

I understand that "%WNL%" is a WeiDU constant for Windows(?!) New Line. I couldn't find it in the WeiDU documentation.

Would you mind letting us(everyone who reads this post, as I am actually only one person) know where to find this?

It's in the documentation, but well hidden: look in section 15, 'WEIDU constants'. In general the WEIDU documentation is difficult to find your way around; the Course in WEIDU I wrote a year ago is sometimes a useful alternative, albeit incomplete in places.

[DavidW]

While I remember, your mod is creating a folder 'stratagems_external/temp'. Can I persuade you to use 'stratagems_external/workspace'? That folder is intended exactly as a 'temp' folder, and I don't think we need two.

[Incrementis]

10 hours ago, DavidW said:

While I remember, your mod is creating a folder 'stratagems_external/temp'. Can I persuade you to use 'stratagems_external/workspace'? That folder is intended exactly as a 'temp' folder, and I don't think we need two.

I'm assuming that by the first stratagems_external/temp you mean weidu_external/temp and therefore asking to change it to stratagems_external/temp.

If that's the case, I'll change it to stratagems_external/temp to keep everything clean and structured.

The only thing that stands out is the word stratagems. What does it mean and do you think its meaning applies to WeiDU externals in general (This won't change my decision unless stratagems means something VERY rude)?

EDIT:

@DavidW Sorry, I missread your comment!

My mod does not create 'stratagems_external/temp', but weidu_external/temp. Is this still an issue?

Edited October 5, 2023 by Incrementis
misunderstanding

[DavidW]

Sorry, I mistyped. ‘Stratagems_external’ is the old name for ‘weidu_external’, before I renamed it encourage other people to use it. Weidu_external/workspace is the temporary-file directory in weidu_external.

It’s not a big deal if there are two temporary file directories, though - I’m just being tidy.

[subtledoctor]

FWIW when I do stuff like this I use

~weidu_external/%MOD_FOLDER%/temp~

or 

~weidu_external/%MOD_FOLDER%/compile~

or 

~weidu_external/%MOD_FOLDER%/backup~

etc. Keeps everything neat and compartmentalized with little or no effort. 

Edited October 6, 2023 by subtledoctor

[Incrementis]

@DavidW Now I understand, thanks for the clarification. Switching to weidu_external/workspace shouldn't be a problem.I will make the minor changes at least for inlined files if subtledoctor's suggestion, ~weidu_external/%MOD_FOLDER%/temp~, for whatever reason doesn't work or results in major changes.

 

4 hours ago, subtledoctor said:

FWIW when I do stuff like this I use

~weidu_external/%MOD_FOLDER%/temp~

or 

~weidu_external/%MOD_FOLDER%/compile~

or 

~weidu_external/%MOD_FOLDER%/backup~

etc. Keeps everything neat and compartmentalized with little or no effort. 

Thanks for the suggestions. They look well thought out.

[DavidW]

On 10/6/2023 at 2:40 AM, subtledoctor said:

FWIW when I do stuff like this I use

~weidu_external/%MOD_FOLDER%/temp~

or 

~weidu_external/%MOD_FOLDER%/compile~

or 

~weidu_external/%MOD_FOLDER%/backup~

etc. Keeps everything neat and compartmentalized with little or no effort. 

That also works fine (call it the CamDawg convention - he’s been doing it that way for ages - as distinct from the DavidW convention; use whichever you like)