Skip to content

Conversation

@Neloreck
Copy link
Contributor

@Neloreck Neloreck commented Jan 14, 2025

Since lua profiler from profiler.script cannot be revived, adding c++ based profiler. For not it is draft with basic POC part, will try to improve it based on other existing implementations. Will add more details in description over time.

Changes

  • Add lua profilers (one is hook based, another is sampling profiler based on luajit profiling API)
  • Update script engine class to optionally include profiler class (initialize profiler for main script engine, ignore resources processor, do not initialize profiler for editor mode)
  • Add application arguments to start with profiler (default, hook, sampling)
  • Export script profiler globals and methods to lua (start, stop, log report, save report)

New command line arguments

  • -lua_profiler start game with default lua scripts profiler (hook variant right now)
  • -lua_hook_profiler start game with hook based scripts profiler
  • -lua_sampling_profiler start game with hook based scripts profiler

New console commands

  • lua_profiler_status - print profiler type/status
  • lua_profiler_start - start profiler in default mode (or provide type as argument)
  • lua_profiler_start_hook_mode - start profiler in hook mdoe
  • ua_profiler_start_sampling_mode - start in sampling mode with 10ms interval (or provide as argument)
  • lua_profiler_stop - stop profiler
  • lua_profiler_reset - reset profiler data
  • lua_profiler_log - log 128 profiler entries (or provide count as argument)
  • lua_profiler_save - save profiling report in a separate .perf/.log file

New Lua exports

  • PROFILER_TYPE_NONE - constant with profiler none type
  • PROFILER_TYPE_HOOK - constant with profiler hook type
  • PROFILER_TYPE_SAMPLING - constant with profiler sampling type
  • profiler.is_active - whether profiler is active now
  • profiler.get_type - currently active profiler type
  • profiler.start - start profiler (default)
  • profiler.start_sampling_mode - start profiler in sampling mode
  • profiler.start_hook_mode - start profiler in hook mode
  • profiler.stop - stop profiler
  • profiler.reset - reset profiler data
  • profiler.log_report - log profiling report
  • profiler.save_report - save profiling report

Testing

  • Test in golden/release/mixed modes
  • Test with JIT enabled/disabled (-nojit parameter)
  • Check resulting logs / resulting report files
  • Start/stop game few times to reinit scripts and validate if everything is OK

Links

@Xottab-DUTY
Copy link
Member

Please, consider using LuaJIT's built-in profiler:
https://luajit.org/ext_profiler.html

@Neloreck
Copy link
Contributor Author

@Xottab-DUTY sounds better
Will check it, ty

@Neloreck
Copy link
Contributor Author

@Xottab-DUTY
Is suggestion to use it as part of profiler here or try to use it inside LUA side? I remember having issues back when I tried to use in scripts part, will give it a try anyway

@Xottab-DUTY
Copy link
Member

@Xottab-DUTY Is suggestion to use it as part of profiler here or try to use it inside LUA side? I remember having issues back when I tried to use in scripts part, will give it a try anyway

The suggestion is to use it here, on the C++ side.
Some info: it's a tracing profiler, so it won't show you 100% info, but will easily help you identify bottlenecks while almost not affecting any performance.
You can add e.g. profiling mode where user can select between the hook-based profiler and LuaJIT's built-in tracing profiler.

@Neloreck
Copy link
Contributor Author

Neloreck commented Jan 14, 2025

@Xottab-DUTY Will try to add simplistic variant with luajit mode to compare it / switch in runtime. I think it will not be too complex if we just print some stats here.

Later something similar to https://github.com/cdsama/LuaProfiler/blob/master/lua_profiler.cpp can be considered, but still need some R&D to understand if I can build traces correctly here.

  • As option profiler results / controls can be added in imgui sections
  • Will not hide it behind debug / mixed defines to allow profiling master-gold variant, will make lua hook conditional / with some lua_gethook checks

u64 total_count = 0;
u64 total_duration = 0;

std::vector<decltype(m_profiling_portions)::iterator> entries;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Always use xr_vector.
If the data isn't too big, you can even use buffer_vector with xr_alloca (there are examples in the code base).

Suggested change
std::vector<decltype(m_profiling_portions)::iterator> entries;
xr_vector<decltype(m_profiling_portions)::iterator> entries;

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For me it was 3-4k records in average. I believe it will be <10k pointers almost always

@Xottab-DUTY Xottab-DUTY added Enhancement SDK Lua Developer Experience Engine's programmer experience Modmaker Experience Modmaker experience with OpenXRay labels Jan 14, 2025
@github-actions github-actions bot added the Game assets A feature or an issue that involves gamedata change label Jan 15, 2025
@Neloreck
Copy link
Contributor Author

@Xottab-DUTY
openxray_neloreck_sampling_profile.zip
https://www.speedscope.app/

image
image
image
image

@Neloreck
Copy link
Contributor Author

Example report console log with hook profiler:

[P] ==================================================================
[P] = Hook profiler report, 4459 entries
[P] ==================================================================
[P] = By calls duration:
[P] ==================================================================
[P] [idx]     sum        sum% |   calls         avg    | trace
[P] [  0]   682.151 ms 17.60% |         2   341.076 ms | func@...medata\core\managers\simulation\SimulationManager.script:56;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46
[P] [  1]   420.145 ms 10.84% |     20205     0.021 ms | preconditionFunction@...a\core\objects\smart_terrain\job\job_precondition.script:111;isJobAvailableToObject@...gamedata\core\objects\smart_terrain\job\job_check.script:11
[P] [  2]   409.004 ms 10.55% |       759     0.539 ms | trySwitchToAnotherSection@...edata\core\schemes\restrictor\sr_idle\IdleManager.script:19;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [  3]   383.098 ms  9.88% |      1834     0.209 ms | pickSectionFromCondList:104;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162
[P] [  4]   325.805 ms  8.41% |         1   325.805 ms | effect@...ripyat\gamedata\scripts\declarations\effects\game.script:128;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [  5]   325.779 ms  8.41% |         3   108.593 ms | createGameSave:30;createGameAutoSave@...ker call of pripyat\gamedata\core\utils\game_save.script:140
[P] [  6]   107.417 ms  2.77% |      4387     0.024 ms | ?:-1;create@[C]:-1
[P] [  7]   104.677 ms  2.70% |      1460     0.072 ms | isFailed@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:214;[C]@...at\gamedata\scripts\declarations\callbacks\custom.script:57
[P] [  8]    96.746 ms  2.50% |       387     0.250 ms | func@...\gamedata\core\managers\treasures\TreasureManager.script:71;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46
[P] [  9]    91.708 ms  2.37% |      1683     0.054 ms | createStalkerJobs@...s\smart_terrain\job\job_create\job_create_stalker.script:30;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36
[P] [ 10]    91.443 ms  2.36% |      1460     0.063 ms | isCompleted@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:210;[C]@...at\gamedata\scripts\declarations\callbacks\custom.script:50
[P] [ 11]    63.689 ms  1.64% |        19     3.352 ms | registerExtensions@...\gamedata\scripts\register\extensions_registrator.script:20;[C]@...on\stalker call of pripyat\gamedata\scripts\start.script:32
[P] [ 12]    55.127 ms  1.42% |       212     0.260 ms | activate@...medata\core\schemes\restrictor\sr_idle\SchemeIdle.script:23;activateSchemeBySection@...f pripyat\gamedata\core\utils\scheme\scheme_logic.script:155
[P] [ 13]    52.332 ms  1.35% |       144     0.363 ms | iterate_inventory@[C]:-1;callback@...ripyat\gamedata\core\binders\creature\ActorBinder.script:93
[P] [ 14]    52.039 ms  1.34% |       144     0.361 ms | addRandomUpgrades@...ripyat\gamedata\core\binders\creature\ActorBinder.script:95;iterate_inventory@[C]:-1
[P] [ 15]    42.560 ms  1.10% |     42901     0.001 ms | sort@[C]:-1;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36
[P] [ 16]    33.445 ms  0.86% |         1    33.445 ms | saveDynamicGameSave@...f pripyat\gamedata\core\managers\save\SaveManager.script:95;execute@[C]:-1
[P] [ 17]    30.906 ms  0.80% |         8     3.863 ms | saveObject@...pyat\gamedata\core\binders\creature\StalkerBinder.script:311;execute@[C]:-1
[P] [ 18]    28.580 ms  0.74% |      2920     0.010 ms | pickSectionFromCondList@...gamedata\scripts\declarations\tasks\task_functors.script:39;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 19]    23.431 ms  0.60% |       556     0.042 ms | registerSimulationObject@...call of pripyat\gamedata\core\database\simulation.script:73;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:317
[P] [ 20]    21.517 ms  0.56% |       949     0.023 ms | registerObjectStoryLinks@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26;create@[C]:-1
[P] [ 21]    19.661 ms  0.51% |       849     0.023 ms | registerObjectStoryLinks@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26;create@[C]:-1
[P] [ 22]    17.479 ms  0.45% |       261     0.067 ms | saveObjectLogic@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120;execute@[C]:-1
[P] [ 23]    15.429 ms  0.40% |       306     0.050 ms | registerSimulationObject@...call of pripyat\gamedata\core\database\simulation.script:73;[C]@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:143
[P] [ 24]    14.999 ms  0.39% |       155     0.097 ms | registerSimulationObject@...call of pripyat\gamedata\core\objects\squad\Squad.script:317;create@[C]:-1
[P] [ 25]    14.792 ms  0.38% |       655     0.023 ms | registerObjectStoryLinks@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26;create@[C]:-1
[P] [ 26]    12.811 ms  0.33% |         8     1.601 ms | forceCorpseReleaseItemsSpawn@...f pripyat\gamedata\core\managers\drop\DropManager.script:38;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:211
[P] [ 27]    10.416 ms  0.27% |        12     0.868 ms | AnomalyZoneBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:42
[P] [ 28]    10.125 ms  0.26% |        14     0.723 ms | activateSchemeBySection:38;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162
[P] [ 29]     9.782 ms  0.25% |        15     0.652 ms | effect@...ipyat\gamedata\scripts\declarations\effects\actor.script:219;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [ 30]     9.731 ms  0.25% |        15     0.649 ms | giveTask@... pripyat\gamedata\core\managers\tasks\TaskManager.script:81;effect@...ipyat\gamedata\scripts\declarations\effects\actor.script:219
[P] [ 31]     9.091 ms  0.23% |       392     0.023 ms | setupStalkerStatePlanner@...amedata\core\ai\planner\setup\setup_state_planner.script:28;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:116
[P] [ 32]     8.826 ms  0.23% |       286     0.031 ms | registerObjectStoryLinks@...of pripyat\gamedata\core\objects\creature\Stalker.script:53;create@[C]:-1
[P] [ 33]     8.676 ms  0.22% |         1     8.676 ms | clientSave@...ripyat\gamedata\core\binders\creature\ActorBinder.script:158;execute@[C]:-1
[P] [ 34]     8.644 ms  0.22% |        20     0.432 ms | clientSave@...f pripyat\gamedata\core\managers\save\SaveManager.script:61;[C]@...ripyat\gamedata\core\binders\creature\ActorBinder.script:158
[P] [ 35]     6.803 ms  0.18% |       294     0.023 ms | registerObjectStoryLinks@...of pripyat\gamedata\core\objects\item\ItemGrenade.script:26;create@[C]:-1
[P] [ 36]     6.427 ms  0.17% |       291     0.022 ms | registerObjectStoryLinks@...all of pripyat\gamedata\core\objects\item\ItemPda.script:26;create@[C]:-1
[P] [ 37]     6.184 ms  0.16% |        74     0.084 ms | getSquadSimulationTarget@...ore\managers\simulation\utils\simulation_priority.script:98;updateCurrentGenericAction@...call of pripyat\gamedata\core\objects\squad\Squad.script:188
[P] [ 38]     5.777 ms  0.15% |         2     2.889 ms | registerSchemes@...yat\gamedata\scripts\register\schemes_registrator.script:122;[C]@...on\stalker call of pripyat\gamedata\scripts\start.script:32
[P] [ 39]     5.511 ms  0.14% |       775     0.007 ms | parseConditionsList@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1
[P] [ 40]     5.227 ms  0.13% |       165     0.032 ms | loadSchemeImplementation:25;loadSchemeImplementations@...f pripyat\gamedata\core\utils\scheme\scheme_setup.script:35
[P] [ 41]     4.993 ms  0.13% |       212     0.024 ms | registerObjectStoryLinks@...gamedata\core\objects\item\ItemWeaponMagazinedWGl.script:26;create@[C]:-1
[P] [ 42]     4.968 ms  0.13% |       155     0.032 ms | registerObjectStoryLinks@...call of pripyat\gamedata\core\objects\squad\Squad.script:317;create@[C]:-1
[P] [ 43]     4.671 ms  0.12% |         5     0.934 ms | give_task@[C]:-1;onActivate@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:287
[P] [ 44]     4.654 ms  0.12% |         5     0.931 ms | emitEvent@...ripyat\gamedata\core\binders\creature\ActorBinder.script:230;give_task@[C]:-1
[P] [ 45]     4.573 ms  0.12% |        88     0.052 ms | iterate_inventory@[C]:-1;filterObjectDeathLoot@...yat\gamedata\core\managers\drop\utils\drop_filter.script:49
[P] [ 46]     4.507 ms  0.12% |        75     0.060 ms | initializeManager@...r call of pripyat\gamedata\core\database\managers.script:14;registerManagers@...at\gamedata\scripts\register\managers_registrator.script:63
[P] [ 47]     4.430 ms  0.11% |      2920     0.002 ms | parseConditionsList@...gamedata\scripts\declarations\tasks\task_functors.script:17;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 48]     4.373 ms  0.11% |       175     0.025 ms | registerObjectStoryLinks@...of pripyat\gamedata\core\objects\creature\Monster.script:41;create@[C]:-1
[P] [ 49]     4.308 ms  0.11% |      2920     0.001 ms | parseConditionsList@...gamedata\scripts\declarations\tasks\task_functors.script:39;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 50]     4.285 ms  0.11% |      4140     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26
[P] [ 51]     3.951 ms  0.10% |       174     0.023 ms | registerObjectStoryLinks@...l of pripyat\gamedata\core\objects\item\ItemTorch.script:26;create@[C]:-1
[P] [ 52]     3.841 ms  0.10% |      3662     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26
[P] [ 53]     3.782 ms  0.10% |      2920     0.001 ms | getObjectIdByStoryId@...gamedata\scripts\declarations\tasks\task_functors.script:39;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 54]     3.738 ms  0.10% |      3708     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26
[P] [ 55]     3.669 ms  0.09% |       330     0.011 ms | condition@...gamedata\scripts\declarations\conditions\relation.script:170;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [ 56]     3.658 ms  0.09% |         1     3.658 ms | effect@...pyat\gamedata\scripts\declarations\effects\object.script:306;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [ 57]     3.649 ms  0.09% |         1     3.649 ms | DoorBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:53
[P] [ 58]     3.457 ms  0.09% |        52     0.066 ms | saveObjectLogic@...t\gamedata\core\binders\physic\PhysicObjectBinder.script:107;execute@[C]:-1
[P] [ 59]     3.393 ms  0.09% |       418     0.008 ms | AnomalyFieldBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:41
[P] [ 60]     3.355 ms  0.09% |       461     0.007 ms | SmartCoverBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:73
[P] [ 61]     3.114 ms  0.08% |        87     0.036 ms | trySwitchToAnotherSection@...core\schemes\physical\ph_door\PhysicalDoorManager.script:83;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [ 62]     2.865 ms  0.07% |       261     0.011 ms | RestrictorBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:71
[P] [ 63]     2.743 ms  0.07% |       610     0.004 ms | isSmartTerrain@...call of pripyat\gamedata\core\objects\squad\Squad.script:339;update@[C]:-1
[P] [ 64]     2.580 ms  0.07% |         6     0.430 ms | initializeManager:14;getManager@...r call of pripyat\gamedata\core\database\managers.script:30
[P] [ 65]     2.339 ms  0.06% |      2070     0.001 ms | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26
[P] [ 66]     2.306 ms  0.06% |       405     0.006 ms | readIniConditionList@... call of pripyat\gamedata\core\utils\ini\ini_read.script:145;getObjectConfigOverrides@...all of pripyat\gamedata\core\utils\ini\ini_config.script:183
[P] [ 67]     2.274 ms  0.06% |      2230     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@... pripyat\gamedata\core\objects\zone\ZoneAnomalous.script:18
[P] [ 68]     2.137 ms  0.06% |       949     0.002 ms | registerObjectDynamicState@...of pripyat\gamedata\core\objects\item\ItemEatable.script:22;create@[C]:-1
[P] [ 69]     2.130 ms  0.05% |      1831     0.001 ms | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26
[P] [ 70]     2.073 ms  0.05% |      1988     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...pripyat\gamedata\core\objects\zone\ZoneRestrictor.script:18
[P] [ 71]     2.025 ms  0.05% |         9     0.225 ms | closeDoor@...core\schemes\physical\ph_door\PhysicalDoorManager.script:40;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [ 72]     2.010 ms  0.05% |        10     0.201 ms | onPlayPdaNotificationSound:319;sendTaskNotification@...a\core\managers\notifications\NotificationManager.script:208
[P] [ 73]     1.972 ms  0.05% |        12     0.164 ms | play@...ripyat\gamedata\core\managers\sounds\SoundManager.script:115;onPlayPdaNotificationSound@...a\core\managers\notifications\NotificationManager.script:319
[P] [ 74]     1.902 ms  0.05% |       261     0.007 ms | closeSaveMarker@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120;execute@[C]:-1
[P] [ 75]     1.831 ms  0.05% |       202     0.009 ms | ____constructor@... of pripyat\gamedata\core\utils\logging\LuaLogger.script:21;__TS__New@...on\stalker call of pripyat\gamedata\lualib_bundle.script:599
[P] [ 76]     1.782 ms  0.05% |       261     0.007 ms | openSaveMarker@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120;execute@[C]:-1
[P] [ 77]     1.723 ms  0.04% |       454     0.004 ms | createObjectJobDescriptor@...ts\smart_terrain\job\job_create\job_create_object.script:15;register_npc@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:186
[P] [ 78]     1.693 ms  0.04% |       155     0.011 ms | setLocationTypesMaskFromSection@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1
[P] [ 79]     1.686 ms  0.04% |       655     0.003 ms | registerObjectDynamicState@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:22;create@[C]:-1
[P] [ 80]     1.642 ms  0.04% |        10     0.164 ms | info@...core\schemes\physical\ph_door\PhysicalDoorManager.script:40;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [ 81]     1.628 ms  0.04% |       849     0.002 ms | registerObjectDynamicState@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:22;create@[C]:-1
[P] [ 82]     1.594 ms  0.04% |        56     0.028 ms | registerObjectStoryLinks@...f pripyat\gamedata\core\objects\item\ItemDetector.script:26;create@[C]:-1
[P] [ 83]     1.571 ms  0.04% |        71     0.022 ms | registerObjectStoryLinks@...r call of pripyat\gamedata\core\objects\item\Item.script:26;create@[C]:-1
[P] [ 84]     1.539 ms  0.04% |         1     1.539 ms | getManager@...r call of pripyat\gamedata\core\database\managers.script:30;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:211
[P] [ 85]     1.517 ms  0.04% |        36     0.042 ms | trySwitchToAnotherSection@...\schemes\physical\ph_button\PhysicalButtonManager.script:29;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [ 86]     1.506 ms  0.04% |      1633     0.001 ms | func@...pripyat\gamedata\core\managers\surge\SurgeManager.script:310;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46
[P] [ 87]     1.458 ms  0.04% |       155     0.009 ms | getStoryManager@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1
[P] [ 88]     1.452 ms  0.04% |        65     0.022 ms | registerObjectStoryLinks@...data\core\objects\item\ItemWeaponAutomaticShotgun.script:26;create@[C]:-1
[P] [ 89]     1.429 ms  0.04% |      1397     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:39
[P] [ 90]     1.409 ms  0.04% |        38     0.037 ms | trySwitchToAnotherSection@...re\schemes\restrictor\sr_particle\ParticleManager.script:83;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [ 91]     1.395 ms  0.04% |      1236     0.001 ms | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26
[P] [ 92]     1.329 ms  0.03% |         3     0.443 ms | switchObjectSchemeToSection:114;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162
[P] [ 93]     1.316 ms  0.03% |         4     0.329 ms | initialize@...f pripyat\gamedata\core\managers\drop\DropManager.script:27;initializeManager@...r call of pripyat\gamedata\core\database\managers.script:14
[P] [ 94]     1.268 ms  0.03% |      1222     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...of pripyat\gamedata\core\objects\item\ItemGrenade.script:26
[P] [ 95]     1.249 ms  0.03% |      1174     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...all of pripyat\gamedata\core\objects\item\ItemPda.script:26
[P] [ 96]     1.236 ms  0.03% |        35     0.035 ms | trySwitchToAnotherSection@...core\schemes\physical\ph_idle\PhysicalIdleManager.script:31;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [ 97]     1.232 ms  0.03% |      1203     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...gamedata\core\objects\item\ItemWeaponMagazinedWGl.script:26
[P] [ 98]     1.164 ms  0.03% |       153     0.008 ms | closeSaveMarker@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:277;execute@[C]:-1
[P] [ 99]     1.142 ms  0.03% |       178     0.006 ms | add@...medata\core\schemes\restrictor\sr_idle\SchemeIdle.script:28;assign@...of pripyat\gamedata\core\ai\scheme\AbstractScheme.script:26
[P] [100]     1.140 ms  0.03% |       155     0.007 ms | closeSaveMarker@...call of pripyat\gamedata\core\objects\squad\Squad.script:268;execute@[C]:-1
[P] [101]     1.130 ms  0.03% |         3     0.377 ms | switchObjectSchemeToSection:109;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162
[P] [102]     1.113 ms  0.03% |        38     0.029 ms | updateComplex@...re\schemes\restrictor\sr_particle\ParticleManager.script:83;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [103]     1.110 ms  0.03% |       155     0.007 ms | openSaveMarker@...call of pripyat\gamedata\core\objects\squad\Squad.script:268;execute@[C]:-1
[P] [104]     1.093 ms  0.03% |        10     0.109 ms | parseConditionsList@...gamedata\scripts\declarations\tasks\task_functors.script:17;____constructor@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:52
[P] [105]     1.091 ms  0.03% |         6     0.182 ms | initialize@...at\gamedata\core\managers\actor\ActorInputManager.script:61;initializeManager@...r call of pripyat\gamedata\core\database\managers.script:14
[P] [106]     1.078 ms  0.03% |       153     0.007 ms | openSaveMarker@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:277;execute@[C]:-1
[P] [107]     1.058 ms  0.03% |         1     1.058 ms | getManager@...r call of pripyat\gamedata\core\database\managers.script:30;initialize@...at\gamedata\core\managers\actor\ActorInputManager.script:61
[P] [108]     1.054 ms  0.03% |        62     0.017 ms | writeTimeToPacket@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:277;execute@[C]:-1
[P] [109]     1.024 ms  0.03% |       946     0.001 ms | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...pripyat\gamedata\core\objects\physic\ObjectPhysic.script:28
[P] [110]     1.024 ms  0.03% |       369     0.003 ms | func@...ripyat\gamedata\core\managers\sounds\SoundManager.script:218;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46
[P] [111]     1.018 ms  0.03% |       286     0.004 ms | readIniString@...of pripyat\gamedata\core\objects\creature\Stalker.script:53;create@[C]:-1
[P] [112]     0.997 ms  0.03% |       291     0.003 ms | registerObjectDynamicState@...all of pripyat\gamedata\core\objects\item\ItemPda.script:22;create@[C]:-1
[P] [113]     0.985 ms  0.03% |       946     0.001 ms | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...pripyat\gamedata\core\objects\physic\ObjectPhysic.script:28
[P] [114]     0.963 ms  0.02% |       136     0.007 ms | getStoryManager@...amedata\core\managers\sounds\utils\sounds_stories.script:12;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:86
[P] [115]     0.941 ms  0.02% |         3     0.314 ms | ____constructor@...ipyat\gamedata\core\managers\events\EventsManager.script:22;__TS__New@...on\stalker call of pripyat\gamedata\lualib_bundle.script:599
[P] [116]     0.921 ms  0.02% |         5     0.184 ms | parseWaypointsData@...re\schemes\restrictor\sr_particle\ParticleManager.script:33;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11
[P] [117]     0.896 ms  0.02% |       174     0.005 ms | getSquadHelpActorTargetId@...f pripyat\gamedata\core\utils\squad\squad_actions.script:54;updateCurrentGenericAction@...call of pripyat\gamedata\core\objects\squad\Squad.script:188
[P] [118]     0.880 ms  0.02% |        88     0.010 ms | shouldFilterLootItem@...yat\gamedata\core\managers\drop\utils\drop_filter.script:56;iterate_inventory@[C]:-1
[P] [119]     0.871 ms  0.02% |       294     0.003 ms | registerObjectDynamicState@...of pripyat\gamedata\core\objects\item\ItemGrenade.script:22;create@[C]:-1
[P] [120]     0.855 ms  0.02% |        95     0.009 ms | WeaponBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:81
[P] [121]     0.790 ms  0.02% |         9     0.088 ms | serverLoad@...f pripyat\gamedata\core\managers\save\SaveManager.script:91;[C]@...l of pripyat\gamedata\core\objects\creature\Actor.script:80
[P] [122]     0.741 ms  0.02% |        40     0.019 ms | activate@...\core\schemes\physical\ph_idle\SchemePhysicalIdle.script:27;activateSchemeBySection@...f pripyat\gamedata\core\utils\scheme\scheme_logic.script:155
[P] [123]     0.737 ms  0.02% |       212     0.003 ms | registerObjectDynamicState@...gamedata\core\objects\item\ItemWeaponMagazinedWGl.script:22;create@[C]:-1
[P] [124]     0.729 ms  0.02% |        12     0.061 ms | serverSave@...f pripyat\gamedata\core\managers\save\SaveManager.script:87;[C]@...l of pripyat\gamedata\core\objects\creature\Actor.script:74
[P] [125]     0.729 ms  0.02% |         7     0.104 ms | activate@...emes\restrictor\sr_crow_spawner\SchemeCrowSpawner.script:26;activateSchemeBySection@...f pripyat\gamedata\core\utils\scheme\scheme_logic.script:155
[P] [126]     0.697 ms  0.02% |         1     0.697 ms | func@...pripyat\gamedata\core\managers\surge\SurgeManager.script:429;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46
[P] [127]     0.696 ms  0.02% |       175     0.004 ms | registerOfflineObject@...of pripyat\gamedata\core\objects\creature\Monster.script:41;create@[C]:-1
[P] ==================================================================
[P] = By calls count:
[P] ==================================================================
[P] [idx]    calls  calls% | trace
[P] [  0]    129857  5.08% | createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36;[C]@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:143
[P] [  1]     84513  3.30% | pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;preconditionFunction@...a\core\objects\smart_terrain\job\job_precondition.script:111
[P] [  2]     77808  3.04% | condition@...t\gamedata\scripts\declarations\conditions\object.script:571;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [  3]     62443  2.44% | condition@...t\gamedata\scripts\declarations\conditions\object.script:127;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [  4]     53410  2.09% | readIniString@... call of pripyat\gamedata\core\utils\ini\ini_read.script:21;registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41
[P] [  5]     52192  2.04% | execute@[C]:-1;executeConsoleCommand@...alker call of pripyat\gamedata\core\utils\console.script:10
[P] [  6]     47517  1.86% | isJobAvailableToObject@...gamedata\core\objects\smart_terrain\job\job_check.script:11;selectTerrainJob@...\gamedata\core\objects\smart_terrain\job\job_pick.script:12
[P] [  7]     42901  1.68% | sort@[C]:-1;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36
[P] [  8]     35222  1.38% | getScriptedSimulationTarget@...call of pripyat\gamedata\core\objects\squad\Squad.script:356;getSimulationTerrainAssignedSquadsCount@...ta\core\managers\simulation\utils\simulation_data.script:16
[P] [  9]     30447  1.19% | create@[C]:-1;addMember@...call of pripyat\gamedata\core\objects\squad\Squad.script:487
[P] [ 10]     27685  1.08% | selectTerrainJob@...\gamedata\core\objects\smart_terrain\job\job_pick.script:12;selectTerrainObjectJob@...data\core\objects\smart_terrain\job\job_execution.script:38
[P] [ 11]     27208  1.06% | initialize:432;[C]@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:328
[P] [ 12]     25704  1.01% | parseStringsList@...call of pripyat\gamedata\core\utils\ini\ini_parse.script:94;check_availability@...amedata\core\animation\animations\scenariosPriA15.script:589
[P] [ 13]     22366  0.87% | createStalkerPointJobs@...t_terrain\job\job_create\job_create_stalker_point.script:15;createStalkerJobs@...s\smart_terrain\job\job_create\job_create_stalker.script:30
[P] [ 14]     21402  0.84% | evaluateSimulationPriority:26;getSlicedSimulationTargets@...ore\managers\simulation\utils\simulation_priority.script:67
[P] [ 15]     20823  0.81% | isValidSimulationTarget@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:598;evaluateSimulationPriority@...ore\managers\simulation\utils\simulation_priority.script:26
[P] [ 16]     20674  0.81% | pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;getScriptedSimulationTarget@...call of pripyat\gamedata\core\objects\squad\Squad.script:356
[P] [ 17]     20496  0.80% | __index@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:72;execute@[C]:-1
[P] [ 18]     20205  0.79% | preconditionFunction@...a\core\objects\smart_terrain\job\job_precondition.script:111;isJobAvailableToObject@...gamedata\core\objects\smart_terrain\job\job_check.script:11
[P] [ 19]     19146  0.75% | createMonsterJobs@...s\smart_terrain\job\job_create\job_create_monster.script:16;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36
[P] [ 20]     19134  0.75% | createExclusiveJob:35;createExclusiveJobs@...smart_terrain\job\job_create\job_create_exclusive.script:111
[P] [ 21]     18772  0.73% | readIniString@... call of pripyat\gamedata\core\utils\ini\ini_read.script:21;createExclusiveJob@...smart_terrain\job\job_create\job_create_exclusive.script:35
[P] [ 22]     18160  0.71% | isStalker@...ker call of pripyat\gamedata\core\utils\class_ids.script:21;condition@...t\gamedata\scripts\declarations\conditions\object.script:571
[P] [ 23]     17920  0.70% | saveObject@...at\gamedata\core\managers\sounds\objects\NpcSound.script:451;saveObject@...ripyat\gamedata\core\managers\sounds\SoundManager.script:101
[P] [ 24]     17238  0.67% | initializeSimulationObjectProperties:31;registerSimulationObject@...call of pripyat\gamedata\core\database\simulation.script:73
[P] [ 25]     17088  0.67% | parseInfoPortions:20;parseConditionsList@...call of pripyat\gamedata\core\utils\ini\ini_parse.script:179
[P] [ 26]     16899  0.66% | readIniString@... call of pripyat\gamedata\core\utils\ini\ini_read.script:21;initialize@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:432
[P] [ 27]     16559  0.65% | copyTable:24;copyTable@...stalker call of pripyat\gamedata\core\utils\table.script:24
[P] [ 28]     16183  0.63% | hasInfoPortion@... call of pripyat\gamedata\core\utils\info_portion.script:54;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42
[P] [ 29]     15795  0.62% | pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;[C]@...gamedata\scripts\declarations\tasks\task_functors.script:39
[P] [ 30]     15768  0.62% | pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 31]     15752  0.62% | parseStringsList@...call of pripyat\gamedata\core\utils\ini\ini_parse.script:94;____constructor@...at\gamedata\core\managers\sounds\objects\NpcSound.script:46
[P] [ 32]     15474  0.61% | addConditions:235;getConfigSwitchConditions@...all of pripyat\gamedata\core\utils\ini\ini_config.script:227
[P] [ 33]     14818  0.58% | readIniString@... call of pripyat\gamedata\core\utils\ini\ini_read.script:21;____constructor@...at\gamedata\core\managers\sounds\objects\NpcSound.script:46
[P] [ 34]     14640  0.57% | info@... of pripyat\gamedata\core\utils\logging\LuaLogger.script:46;register_npc@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:186
[P] [ 35]     14490  0.57% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26
[P] [ 36]     14182  0.55% | check_availability:589;createSequenceForNpc@...amedata\core\animation\animations\scenariosPriA15.script:601
[P] [ 37]     13020  0.51% | __index@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:27;[C]@[C]:-1
[P] [ 38]     12984  0.51% | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:233;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26
[P] [ 39]     12848  0.50% | updateLevelDirection:272;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 40]     12817  0.50% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26
[P] [ 41]     12776  0.50% | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:233;[C]@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26
[P] [ 42]     12740  0.50% | __newindex@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:101;[C]@[C]:-1
[P] [ 43]     12442  0.49% | update@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:384;[C]@...ata\core\binders\smart_terrain\SmartTerrainBinder.script:57
[P] [ 44]     12408  0.49% | areObjectsOnSameLevel@...lker call of pripyat\gamedata\core\utils\position.script:109;evaluateSimulationPriority@...ore\managers\simulation\utils\simulation_priority.script:26
[P] [ 45]     12359  0.48% | ____constructor@...at\gamedata\core\managers\sounds\objects\NpcSound.script:46;__TS__New@...on\stalker call of pripyat\gamedata\lualib_bundle.script:599
[P] [ 46]     12264  0.48% | pairs@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 47]     11972  0.47% | update:221;isCompleted@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:210
[P] [ 48]     11972  0.47% | update:221;isFailed@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:214
[P] [ 49]     11053  0.43% | spawnTreasure:157;spawnTreasures@...\gamedata\core\managers\treasures\TreasureManager.script:147
[P] [ 50]     10474  0.41% | register_npc@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:186;assignMemberToTerrain@...call of pripyat\gamedata\core\objects\squad\Squad.script:432
[P] [ 51]     10077  0.39% | getSlicedSimulationTargets:67;getSquadSimulationTarget@...ore\managers\simulation\utils\simulation_priority.script:98
[P] [ 52]      9971  0.39% | updateSquadMapSpot@...t\gamedata\core\managers\map\utils\map_spot_squad.script:31;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:171
[P] [ 53]      9900  0.39% | setupSimulationObjectSquadAndGroup:116;createSimulationSquad@...\core\managers\simulation\utils\simulation_squads.script:191
[P] [ 54]      9779  0.38% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:39
[P] [ 55]      9535  0.37% | isObjectArrivedToTerrain@...objects\smart_terrain\object\smart_terrain_object.script:37;register_npc@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:186
[P] [ 56]      9470  0.37% | readIniBoolean@... call of pripyat\gamedata\core\utils\ini\ini_read.script:110;____constructor@...at\gamedata\core\managers\sounds\objects\NpcSound.script:46
[P] [ 57]      9334  0.36% | register_npc:186;[C]@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:143
[P] [ 58]      9080  0.36% | __index@[C]:-1;condition@...t\gamedata\scripts\declarations\conditions\object.script:571
[P] [ 59]      8652  0.34% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26
[P] [ 60]      8253  0.32% | assignMemberToTerrain:432;assignToTerrain@...call of pripyat\gamedata\core\objects\squad\Squad.script:446
[P] [ 61]      7996  0.31% | pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;[C]@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:104
[P] [ 62]      7898  0.31% | create@[C]:-1;spawnTreasure@...\gamedata\core\managers\treasures\TreasureManager.script:157
[P] [ 63]      7868  0.31% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...pripyat\gamedata\core\objects\zone\ZoneRestrictor.script:18
[P] [ 64]      7805  0.31% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@... pripyat\gamedata\core\objects\zone\ZoneAnomalous.script:18
[P] [ 65]      7725  0.30% | assignToTerrain@...call of pripyat\gamedata\core\objects\squad\Squad.script:446;assignSimulationSquadToTerrain@...\core\managers\simulation\utils\simulation_squads.script:141
[P] [ 66]      7695  0.30% | createSequenceForNpc:601;[C]@...amedata\core\animation\animations\scenariosPriA15.script:0
[P] [ 67]      7655  0.30% | readIniString@... call of pripyat\gamedata\core\utils\ini\ini_read.script:21;readUpgradeGroup@...amedata\core\managers\upgrades\utils\upgrades_get.script:15
[P] [ 68]      7454  0.29% | w_stringZ@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:72;execute@[C]:-1
[P] [ 69]      7296  0.29% | setObjectTeamSquadGroup@...ker call of pripyat\gamedata\core\utils\community.script:34;setupSimulationObjectSquadAndGroup@...\core\managers\simulation\utils\simulation_squads.script:116
[P] [ 70]      7074  0.28% | parseConditionsList@...call of pripyat\gamedata\core\utils\ini\ini_parse.script:179;createExclusiveJob@...smart_terrain\job\job_create\job_create_exclusive.script:35
[P] [ 71]      7008  0.27% | hasInfoPortion@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221
[P] [ 72]      6930  0.27% | setupSimulationObjectSquadAndGroup@...\core\managers\simulation\utils\simulation_squads.script:116;onSimulationTargetDeselected@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:674
[P] [ 73]      6885  0.27% | setupCallbacks:120;[C]@...t\gamedata\core\binders\physic\PhysicObjectBinder.script:92
[P] [ 74]      6835  0.27% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...pripyat\gamedata\core\objects\physic\ObjectPhysic.script:28
[P] [ 75]      6830  0.27% | __index@[C]:-1;areObjectsOnSameLevel@...lker call of pripyat\gamedata\core\utils\position.script:109
[P] [ 76]      6772  0.26% | __index@...call of pripyat\gamedata\core\objects\squad\Squad.script:339;update@[C]:-1
[P] [ 77]      6746  0.26% | trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162;[C]@...edata\core\schemes\restrictor\sr_idle\IdleManager.script:19
[P] [ 78]      6621  0.26% | saveObjectLogic@...lker call of pripyat\gamedata\core\database\logic.script:27;[C]@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120
[P] [ 79]      6592  0.26% | __index@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:72;[C]@[C]:-1
[P] [ 80]      6510  0.25% | __newindex@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:27;[C]@[C]:-1
[P] [ 81]      6444  0.25% | setLocationTypesMaskFromSection:453;setLocationTypes@...call of pripyat\gamedata\core\objects\squad\Squad.script:459
[P] [ 82]      6360  0.25% | saveObject@...ripyat\gamedata\core\managers\sounds\SoundManager.script:101;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:311
[P] [ 83]      6323  0.25% | getSimulationTerrainAssignedSquadsCount@...ta\core\managers\simulation\utils\simulation_data.script:16;assignSimulationSquadToTerrain@...\core\managers\simulation\utils\simulation_squads.script:141
[P] [ 84]      6283  0.25% | getSimulationTerrainAssignedSquadsCount@...ta\core\managers\simulation\utils\simulation_data.script:16;isValidSimulationTarget@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:598
[P] [ 85]      6057  0.24% | w_bool@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:72;execute@[C]:-1
[P] [ 86]      5885  0.23% | areObjectsOnSameLevel@...lker call of pripyat\gamedata\core\utils\position.script:109;update@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:384
[P] [ 87]      5682  0.22% | getScriptedSimulationTarget:356;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:171
[P] [ 88]      5660  0.22% | readUpgradeGroup:15;readUpgradeGroup@...amedata\core\managers\upgrades\utils\upgrades_get.script:15
[P] [ 89]      5639  0.22% | createStalkerWalkerJobs@..._terrain\job\job_create\job_create_stalker_walker.script:19;createStalkerJobs@...s\smart_terrain\job\job_create\job_create_stalker.script:30
[P] [ 90]      5610  0.22% | parseStringsList@...call of pripyat\gamedata\core\utils\ini\ini_parse.script:94;readUpgradeGroup@...amedata\core\managers\upgrades\utils\upgrades_get.script:15
[P] [ 91]      5551  0.22% | addMember@...call of pripyat\gamedata\core\objects\squad\Squad.script:487;createSimulationSquadMembers@...\core\managers\simulation\utils\simulation_squads.script:46
[P] [ 92]      5472  0.21% | __newindex@[C]:-1;setObjectTeamSquadGroup@...ker call of pripyat\gamedata\core\utils\community.script:34
[P] [ 93]      5472  0.21% | __index@[C]:-1;setupSimulationObjectSquadAndGroup@...\core\managers\simulation\utils\simulation_squads.script:116
[P] [ 94]      5445  0.21% | areObjectsOnSameLevel@...lker call of pripyat\gamedata\core\utils\position.script:109;[C]@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:384
[P] [ 95]      5403  0.21% | registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:233;[C]@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26
[P] [ 96]      5359  0.21% | __index@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:277;execute@[C]:-1
[P] [ 97]      5115  0.20% | readIniTreasuresList@...data\core\managers\treasures\utils\treasures_init.script:25;[C]@...t\gamedata\core\managers\treasures\TreasureConfig.script:0
[P] [ 98]      5038  0.20% | __index@[C]:-1;getSlicedSimulationTargets@...ore\managers\simulation\utils\simulation_priority.script:67
[P] [ 99]      5026  0.20% | writeTimeToPacket@...\stalker call of pripyat\gamedata\core\utils\time.script:99;saveObjectLogic@...lker call of pripyat\gamedata\core\database\logic.script:27
[P] [100]      4985  0.19% | createSimulationSquadMembers:46;createSimulationSquad@...\core\managers\simulation\utils\simulation_squads.script:191
[P] [101]      4950  0.19% | areObjectsOnSameLevel@...lker call of pripyat\gamedata\core\utils\position.script:109;addMember@...call of pripyat\gamedata\core\objects\squad\Squad.script:487
[P] [102]      4940  0.19% | info@... of pripyat\gamedata\core\utils\logging\LuaLogger.script:46;createExclusiveJob@...smart_terrain\job\job_create\job_create_exclusive.script:35
[P] [103]      4908  0.19% | readIniNumber@... call of pripyat\gamedata\core\utils\ini\ini_read.script:93;createExclusiveJob@...smart_terrain\job\job_create\job_create_exclusive.script:35
[P] [104]      4826  0.19% | readIniBoolean@... call of pripyat\gamedata\core\utils\ini\ini_read.script:110;createExclusiveJob@...smart_terrain\job\job_create\job_create_exclusive.script:35
[P] [105]      4805  0.19% | __newindex@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1
[P] [106]      4741  0.19% | getServerDistanceBetween@...talker call of pripyat\gamedata\core\utils\vertex.script:21;evaluateSimulationPriorityByDistance@...ore\managers\simulation\utils\simulation_priority.script:15
[P] [107]      4733  0.19% | parseFunctionParams:82;parseInfoPortions@...call of pripyat\gamedata\core\utils\ini\ini_parse.script:20
[P] [108]      4620  0.18% | readIniString@... call of pripyat\gamedata\core\utils\ini\ini_read.script:21;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:86
[P] [109]      4542  0.18% | applySmartTerrainRespawnSectionsConfig@...e\objects\smart_terrain\spawn\smart_terrain_spawn.script:25;initialize@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:432
[P] [110]      4464  0.17% | selectTerrainObjectJob:38;updateTerrainJobs@...data\core\objects\smart_terrain\job\job_execution.script:78
[P] [111]      4420  0.17% | readIniBoolean@... call of pripyat\gamedata\core\utils\ini\ini_read.script:110;initialize@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:432
[P] [112]      4402  0.17% | func@...\gamedata\core\managers\treasures\TreasureManager.script:274;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46
[P] [113]      4387  0.17% | ?:-1;create@[C]:-1
[P] [114]      4362  0.17% | createStalkerGuardJobs@...t_terrain\job\job_create\job_create_stalker_guard.script:20;createStalkerJobs@...s\smart_terrain\job\job_create\job_create_stalker.script:30
[P] [115]      4312  0.17% | activateSchemeBySection@...f pripyat\gamedata\core\utils\scheme\scheme_logic.script:155;initializeObjectSchemeLogic@...\gamedata\core\utils\scheme\scheme_initialization.script:155
[P] [116]      4280  0.17% | updateCurrentScriptedAction:236;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:171
[P] [117]      4277  0.17% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...of pripyat\gamedata\core\objects\item\ItemGrenade.script:26
[P] [118]      4255  0.17% | __index@[C]:-1;getScriptedSimulationTarget@...call of pripyat\gamedata\core\objects\squad\Squad.script:356
[P] [119]      4245  0.17% | getSquadMembersRelationToActor@...pripyat\gamedata\core\utils\relation\relation_get.script:60;updateSquadMapSpot@...t\gamedata\core\managers\map\utils\map_spot_squad.script:31
[P] [120]      4233  0.17% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...of pripyat\gamedata\core\objects\creature\Stalker.script:53
[P] [121]      4214  0.16% | registerObjectStoryLinks@...l of pripyat\gamedata\core\database\story_objects.script:41;[C]@...all of pripyat\gamedata\core\objects\item\ItemPda.script:26
[P] [122]      4140  0.16% | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26
[P] [123]      4140  0.16% | emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26
[P] [124]      4106  0.16% | createExclusiveJobs@...smart_terrain\job\job_create\job_create_exclusive.script:111;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36
[P] [125]      4088  0.16% | removeGuiderSpot@...\gamedata\core\managers\tasks\utils\tasks_generic.script:25;updateLevelDirection@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:272
[P] [126]      4086  0.16% | selectTerrainObjectJob@...data\core\objects\smart_terrain\job\job_execution.script:38;register_npc@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:186
[P] [127]      4064  0.16% | readIniGenericDialogs@...\gamedata\core\managers\dialogs\utils\dialog_read.script:17;[C]@...ipyat\gamedata\core\managers\dialogs\DialogConfig.script:0
[P] ==================================================================
[P] = Total function calls count: 2557543
[P] = Total function calls duration: 3875.933105 ms
[P] ==================================================================

@Neloreck
Copy link
Contributor Author

Neloreck commented Jan 18, 2025

Exported hook profiler data (trimmed, 4460 lines in the file):
openxray_neloreck_hook_profile.log

trace:func@...medata\core\managers\simulation\SimulationManager.script:56;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46 calls:2 avg:341.076ms sum:682.151ms 
trace:preconditionFunction@...a\core\objects\smart_terrain\job\job_precondition.script:111;isJobAvailableToObject@...gamedata\core\objects\smart_terrain\job\job_check.script:11 calls:20205 avg:0.021ms sum:420.145ms 
trace:trySwitchToAnotherSection@...edata\core\schemes\restrictor\sr_idle\IdleManager.script:19;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:759 avg:0.539ms sum:409.004ms 
trace:pickSectionFromCondList:104;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162 calls:1834 avg:0.209ms sum:383.098ms 
trace:effect@...ripyat\gamedata\scripts\declarations\effects\game.script:128;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42 calls:1 avg:325.805ms sum:325.805ms 
trace:createGameSave:30;createGameAutoSave@...ker call of pripyat\gamedata\core\utils\game_save.script:140 calls:3 avg:108.593ms sum:325.779ms 
trace:?:-1;create@[C]:-1 calls:4387 avg:0.024ms sum:107.417ms 
trace:isFailed@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:214;[C]@...at\gamedata\scripts\declarations\callbacks\custom.script:57 calls:1460 avg:0.072ms sum:104.677ms 
trace:func@...\gamedata\core\managers\treasures\TreasureManager.script:71;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46 calls:387 avg:0.250ms sum:96.746ms 
trace:createStalkerJobs@...s\smart_terrain\job\job_create\job_create_stalker.script:30;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36 calls:1683 avg:0.054ms sum:91.708ms 
trace:isCompleted@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:210;[C]@...at\gamedata\scripts\declarations\callbacks\custom.script:50 calls:1460 avg:0.063ms sum:91.443ms 
trace:registerExtensions@...\gamedata\scripts\register\extensions_registrator.script:20;[C]@...on\stalker call of pripyat\gamedata\scripts\start.script:32 calls:19 avg:3.352ms sum:63.689ms 
trace:activate@...medata\core\schemes\restrictor\sr_idle\SchemeIdle.script:23;activateSchemeBySection@...f pripyat\gamedata\core\utils\scheme\scheme_logic.script:155 calls:212 avg:0.260ms sum:55.127ms 
trace:iterate_inventory@[C]:-1;callback@...ripyat\gamedata\core\binders\creature\ActorBinder.script:93 calls:144 avg:0.363ms sum:52.332ms 
trace:addRandomUpgrades@...ripyat\gamedata\core\binders\creature\ActorBinder.script:95;iterate_inventory@[C]:-1 calls:144 avg:0.361ms sum:52.039ms 
trace:sort@[C]:-1;createTerrainJobs@...e\objects\smart_terrain\job\job_create\job_create.script:36 calls:42901 avg:0.001ms sum:42.560ms 
trace:saveDynamicGameSave@...f pripyat\gamedata\core\managers\save\SaveManager.script:95;execute@[C]:-1 calls:1 avg:33.445ms sum:33.445ms 
trace:saveObject@...pyat\gamedata\core\binders\creature\StalkerBinder.script:311;execute@[C]:-1 calls:8 avg:3.863ms sum:30.906ms 
trace:pickSectionFromCondList@...gamedata\scripts\declarations\tasks\task_functors.script:39;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221 calls:2920 avg:0.010ms sum:28.580ms 
trace:registerSimulationObject@...call of pripyat\gamedata\core\database\simulation.script:73;[C]@...call of pripyat\gamedata\core\objects\squad\Squad.script:317 calls:556 avg:0.042ms sum:23.431ms 
trace:registerObjectStoryLinks@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26;create@[C]:-1 calls:949 avg:0.023ms sum:21.517ms 
trace:registerObjectStoryLinks@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26;create@[C]:-1 calls:849 avg:0.023ms sum:19.661ms 
trace:saveObjectLogic@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120;execute@[C]:-1 calls:261 avg:0.067ms sum:17.479ms 
trace:registerSimulationObject@...call of pripyat\gamedata\core\database\simulation.script:73;[C]@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:143 calls:306 avg:0.050ms sum:15.429ms 
trace:registerSimulationObject@...call of pripyat\gamedata\core\objects\squad\Squad.script:317;create@[C]:-1 calls:155 avg:0.097ms sum:14.999ms 
trace:registerObjectStoryLinks@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26;create@[C]:-1 calls:655 avg:0.023ms sum:14.792ms 
trace:forceCorpseReleaseItemsSpawn@...f pripyat\gamedata\core\managers\drop\DropManager.script:38;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:211 calls:8 avg:1.601ms sum:12.811ms 
trace:AnomalyZoneBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:42 calls:12 avg:0.868ms sum:10.416ms 
trace:activateSchemeBySection:38;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162 calls:14 avg:0.723ms sum:10.125ms 
trace:effect@...ipyat\gamedata\scripts\declarations\effects\actor.script:219;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42 calls:15 avg:0.652ms sum:9.782ms 
trace:giveTask@... pripyat\gamedata\core\managers\tasks\TaskManager.script:81;effect@...ipyat\gamedata\scripts\declarations\effects\actor.script:219 calls:15 avg:0.649ms sum:9.731ms 
trace:setupStalkerStatePlanner@...amedata\core\ai\planner\setup\setup_state_planner.script:28;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:116 calls:392 avg:0.023ms sum:9.091ms 
trace:registerObjectStoryLinks@...of pripyat\gamedata\core\objects\creature\Stalker.script:53;create@[C]:-1 calls:286 avg:0.031ms sum:8.826ms 
trace:clientSave@...ripyat\gamedata\core\binders\creature\ActorBinder.script:158;execute@[C]:-1 calls:1 avg:8.676ms sum:8.676ms 
trace:clientSave@...f pripyat\gamedata\core\managers\save\SaveManager.script:61;[C]@...ripyat\gamedata\core\binders\creature\ActorBinder.script:158 calls:20 avg:0.432ms sum:8.644ms 
trace:registerObjectStoryLinks@...of pripyat\gamedata\core\objects\item\ItemGrenade.script:26;create@[C]:-1 calls:294 avg:0.023ms sum:6.803ms 
trace:registerObjectStoryLinks@...all of pripyat\gamedata\core\objects\item\ItemPda.script:26;create@[C]:-1 calls:291 avg:0.022ms sum:6.427ms 
trace:getSquadSimulationTarget@...ore\managers\simulation\utils\simulation_priority.script:98;updateCurrentGenericAction@...call of pripyat\gamedata\core\objects\squad\Squad.script:188 calls:74 avg:0.084ms sum:6.184ms 
trace:registerSchemes@...yat\gamedata\scripts\register\schemes_registrator.script:122;[C]@...on\stalker call of pripyat\gamedata\scripts\start.script:32 calls:2 avg:2.889ms sum:5.777ms 
trace:parseConditionsList@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1 calls:775 avg:0.007ms sum:5.511ms 
trace:loadSchemeImplementation:25;loadSchemeImplementations@...f pripyat\gamedata\core\utils\scheme\scheme_setup.script:35 calls:165 avg:0.032ms sum:5.227ms 
trace:registerObjectStoryLinks@...gamedata\core\objects\item\ItemWeaponMagazinedWGl.script:26;create@[C]:-1 calls:212 avg:0.024ms sum:4.993ms 
trace:registerObjectStoryLinks@...call of pripyat\gamedata\core\objects\squad\Squad.script:317;create@[C]:-1 calls:155 avg:0.032ms sum:4.968ms 
trace:give_task@[C]:-1;onActivate@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:287 calls:5 avg:0.934ms sum:4.671ms 
trace:emitEvent@...ripyat\gamedata\core\binders\creature\ActorBinder.script:230;give_task@[C]:-1 calls:5 avg:0.931ms sum:4.654ms 
trace:iterate_inventory@[C]:-1;filterObjectDeathLoot@...yat\gamedata\core\managers\drop\utils\drop_filter.script:49 calls:88 avg:0.052ms sum:4.573ms 
trace:initializeManager@...r call of pripyat\gamedata\core\database\managers.script:14;registerManagers@...at\gamedata\scripts\register\managers_registrator.script:63 calls:75 avg:0.060ms sum:4.507ms 
trace:parseConditionsList@...gamedata\scripts\declarations\tasks\task_functors.script:17;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221 calls:2920 avg:0.002ms sum:4.430ms 
trace:registerObjectStoryLinks@...of pripyat\gamedata\core\objects\creature\Monster.script:41;create@[C]:-1 calls:175 avg:0.025ms sum:4.373ms 
trace:parseConditionsList@...gamedata\scripts\declarations\tasks\task_functors.script:39;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221 calls:2920 avg:0.001ms sum:4.308ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26 calls:4140 avg:0.001ms sum:4.285ms 
trace:registerObjectStoryLinks@...l of pripyat\gamedata\core\objects\item\ItemTorch.script:26;create@[C]:-1 calls:174 avg:0.023ms sum:3.951ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26 calls:3662 avg:0.001ms sum:3.841ms 
trace:getObjectIdByStoryId@...gamedata\scripts\declarations\tasks\task_functors.script:39;update@...f pripyat\gamedata\core\managers\tasks\TaskObject.script:221 calls:2920 avg:0.001ms sum:3.782ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26 calls:3708 avg:0.001ms sum:3.738ms 
trace:condition@...gamedata\scripts\declarations\conditions\relation.script:170;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42 calls:330 avg:0.011ms sum:3.669ms 
trace:effect@...pyat\gamedata\scripts\declarations\effects\object.script:306;pickSectionFromCondList@...all of pripyat\gamedata\core\utils\ini\ini_config.script:42 calls:1 avg:3.658ms sum:3.658ms 
trace:DoorBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:53 calls:1 avg:3.649ms sum:3.649ms 
trace:saveObjectLogic@...t\gamedata\core\binders\physic\PhysicObjectBinder.script:107;execute@[C]:-1 calls:52 avg:0.066ms sum:3.457ms 
trace:AnomalyFieldBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:41 calls:418 avg:0.008ms sum:3.393ms 
trace:SmartCoverBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:73 calls:461 avg:0.007ms sum:3.355ms 
trace:trySwitchToAnotherSection@...core\schemes\physical\ph_door\PhysicalDoorManager.script:83;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:87 avg:0.036ms sum:3.114ms 
trace:RestrictorBinder@[C]:-1;[C]@...mon\stalker call of pripyat\gamedata\scripts\bind.script:71 calls:261 avg:0.011ms sum:2.865ms 
trace:isSmartTerrain@...call of pripyat\gamedata\core\objects\squad\Squad.script:339;update@[C]:-1 calls:610 avg:0.004ms sum:2.743ms 
trace:initializeManager:14;getManager@...r call of pripyat\gamedata\core\database\managers.script:30 calls:6 avg:0.430ms sum:2.580ms 
trace:registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...of pripyat\gamedata\core\objects\item\ItemEatable.script:26 calls:2070 avg:0.001ms sum:2.339ms 
trace:readIniConditionList@... call of pripyat\gamedata\core\utils\ini\ini_read.script:145;getObjectConfigOverrides@...all of pripyat\gamedata\core\utils\ini\ini_config.script:183 calls:405 avg:0.006ms sum:2.306ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@... pripyat\gamedata\core\objects\zone\ZoneAnomalous.script:18 calls:2230 avg:0.001ms sum:2.274ms 
trace:registerObjectDynamicState@...of pripyat\gamedata\core\objects\item\ItemEatable.script:22;create@[C]:-1 calls:949 avg:0.002ms sum:2.137ms 
trace:registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:26 calls:1831 avg:0.001ms sum:2.130ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...pripyat\gamedata\core\objects\zone\ZoneRestrictor.script:18 calls:1988 avg:0.001ms sum:2.073ms 
trace:closeDoor@...core\schemes\physical\ph_door\PhysicalDoorManager.script:40;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:9 avg:0.225ms sum:2.025ms 
trace:onPlayPdaNotificationSound:319;sendTaskNotification@...a\core\managers\notifications\NotificationManager.script:208 calls:10 avg:0.201ms sum:2.010ms 
trace:play@...ripyat\gamedata\core\managers\sounds\SoundManager.script:115;onPlayPdaNotificationSound@...a\core\managers\notifications\NotificationManager.script:319 calls:12 avg:0.164ms sum:1.972ms 
trace:closeSaveMarker@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120;execute@[C]:-1 calls:261 avg:0.007ms sum:1.902ms 
trace:____constructor@... of pripyat\gamedata\core\utils\logging\LuaLogger.script:21;__TS__New@...on\stalker call of pripyat\gamedata\lualib_bundle.script:599 calls:202 avg:0.009ms sum:1.831ms 
trace:openSaveMarker@...pyat\gamedata\core\binders\zones\RestrictorBinder.script:120;execute@[C]:-1 calls:261 avg:0.007ms sum:1.782ms 
trace:createObjectJobDescriptor@...ts\smart_terrain\job\job_create\job_create_object.script:15;register_npc@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:186 calls:454 avg:0.004ms sum:1.723ms 
trace:setLocationTypesMaskFromSection@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1 calls:155 avg:0.011ms sum:1.693ms 
trace:registerObjectDynamicState@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:22;create@[C]:-1 calls:655 avg:0.003ms sum:1.686ms 
trace:info@...core\schemes\physical\ph_door\PhysicalDoorManager.script:40;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:10 avg:0.164ms sum:1.642ms 
trace:registerObjectDynamicState@...ll of pripyat\gamedata\core\objects\item\ItemAmmo.script:22;create@[C]:-1 calls:849 avg:0.002ms sum:1.628ms 
trace:registerObjectStoryLinks@...f pripyat\gamedata\core\objects\item\ItemDetector.script:26;create@[C]:-1 calls:56 avg:0.028ms sum:1.594ms 
trace:registerObjectStoryLinks@...r call of pripyat\gamedata\core\objects\item\Item.script:26;create@[C]:-1 calls:71 avg:0.022ms sum:1.571ms 
trace:getManager@...r call of pripyat\gamedata\core\database\managers.script:30;[C]@...pyat\gamedata\core\binders\creature\StalkerBinder.script:211 calls:1 avg:1.539ms sum:1.539ms 
trace:trySwitchToAnotherSection@...\schemes\physical\ph_button\PhysicalButtonManager.script:29;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:36 avg:0.042ms sum:1.517ms 
trace:func@...pripyat\gamedata\core\managers\surge\SurgeManager.script:310;emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:46 calls:1633 avg:0.001ms sum:1.506ms 
trace:getStoryManager@...call of pripyat\gamedata\core\objects\squad\Squad.script:86;[C]@[C]:-1 calls:155 avg:0.009ms sum:1.458ms 
trace:registerObjectStoryLinks@...data\core\objects\item\ItemWeaponAutomaticShotgun.script:26;create@[C]:-1 calls:65 avg:0.022ms sum:1.452ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...pyat\gamedata\core\objects\smart_cover\SmartCover.script:39 calls:1397 avg:0.001ms sum:1.429ms 
trace:trySwitchToAnotherSection@...re\schemes\restrictor\sr_particle\ParticleManager.script:83;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:38 avg:0.037ms sum:1.409ms 
trace:registerItem@...\gamedata\core\managers\treasures\TreasureManager.script:54;[C]@...at\gamedata\core\objects\item\ItemWeaponMagazined.script:26 calls:1236 avg:0.001ms sum:1.395ms 
trace:switchObjectSchemeToSection:114;trySwitchToAnotherSection@... pripyat\gamedata\core\utils\scheme\scheme_switch.script:162 calls:3 avg:0.443ms sum:1.329ms 
trace:initialize@...f pripyat\gamedata\core\managers\drop\DropManager.script:27;initializeManager@...r call of pripyat\gamedata\core\database\managers.script:14 calls:4 avg:0.329ms sum:1.316ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...of pripyat\gamedata\core\objects\item\ItemGrenade.script:26 calls:1222 avg:0.001ms sum:1.268ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...all of pripyat\gamedata\core\objects\item\ItemPda.script:26 calls:1174 avg:0.001ms sum:1.249ms 
trace:trySwitchToAnotherSection@...core\schemes\physical\ph_idle\PhysicalIdleManager.script:31;emitSchemeEvent@...f pripyat\gamedata\core\utils\scheme\scheme_event.script:11 calls:35 avg:0.035ms sum:1.236ms 
trace:emitEvent@...ipyat\gamedata\core\managers\events\EventsManager.script:35;[C]@...gamedata\core\objects\item\ItemWeaponMagazinedWGl.script:26 calls:1203 avg:0.001ms sum:1.232ms 
trace:closeSaveMarker@...\gamedata\core\objects\smart_terrain\SmartTerrain.script:277;execute@[C]:-1 calls:153 avg:0.008ms sum:1.164ms 
trace:add@...medata\core\schemes\restrictor\sr_idle\SchemeIdle.script:28;assign@...of pripyat\gamedata\core\ai\scheme\AbstractScheme.script:26 calls:178 avg:0.006ms sum:1.142ms 
trace:closeSaveMarker@...call of pripyat\gamedata\core\objects\squad\Squad.script:268;execute@[C]:-1 calls:155 avg:0.007ms sum:1.140ms 
...

@Neloreck
Copy link
Contributor Author

Console reported log for sampling profiler:

[P] ==================================================================
[P] = Sampling profiler report, 666 entries
[P] ==================================================================
[P] [idx]  samples    %    | trace
[P] [  0]     10163 43.45% | ActorBinder.script:123ActorBinder.script:124
[P] [  1]      7070 30.23% | quests.script:677quests.script:678
[P] [  2]      1817  7.77% | MainMenu.script:317MainMenu.script:318
[P] [  3]       816  3.49% | ZoneRestrictor.script:30ZoneRestrictor.script:31
[P] [  4]       379  1.62% | StalkerBinder.script:116StalkerBinder.script:117
[P] [  5]       334  1.43% | MainMenu.script:53MainMenu.script:54
[P] [  6]       170  0.73% | ZoneAnomalous.script:15ZoneAnomalous.script:16
[P] [  7]       167  0.71% | WeaponBinder.script:46WeaponBinder.script:47
[P] [  8]       159  0.68% | createExclusiveJobjob_create_exclusive.script:48
[P] [  9]       108  0.46% | SmartCover.script:27SmartCover.script:28
[P] [ 10]        89  0.38% | ZoneRestrictor.script:15ZoneRestrictor.script:16
[P] [ 11]        83  0.35% | custom.script:57custom.script:58
[P] [ 12]        66  0.28% | ItemPda.script:18ItemPda.script:19
[P] [ 13]        63  0.27% | interface.script:54interface.script:54
[P] [ 14]        54  0.23% | index.script:0index.script:3
[P] [ 15]        50  0.21% | ItemArtefact.script:38ItemArtefact.script:39
[P] [ 16]        50  0.21% | infoLuaLogger.script:67
[P] [ 17]        49  0.21% | areObjectsOnSameLevelposition.script:111
[P] [ 18]        48  0.21% | ItemAmmo.script:39ItemAmmo.script:40
[P] [ 19]        47  0.20% | registerObjectStoryLinksstory_objects.script:43
[P] [ 20]        43  0.18% | bind.script:65bind.script:66
[P] [ 21]        38  0.16% | PhysicalDoorManager.script:92PhysicalDoorManager.script:93
[P] [ 22]        37  0.16% | ObjectPhysic.script:24ObjectPhysic.script:25
[P] [ 23]        30  0.13% | ItemEatable.script:39ItemEatable.script:40
[P] [ 24]        28  0.12% | createTerrainJobsjob_create.script:113
[P] [ 25]        24  0.10% | RestrictorBinder.script:88RestrictorBinder.script:91
[P] [ 26]        24  0.10% | initializeSmartTerrain.script:443
[P] [ 27]        22  0.09% | registerItemTreasureManager.script:235
[P] [ 28]        22  0.09% | bind.script:41bind.script:41
[P] [ 29]        21  0.09% | SmartCover.script:72SmartCover.script:73
[P] [ 30]        21  0.09% | RestrictorBinder.script:88RestrictorBinder.script:89
[P] [ 31]        20  0.09% | OutfitBinder.script:46OutfitBinder.script:47
[P] [ 32]        19  0.08% | loadDynamicIniFileini.script:29
[P] [ 33]        17  0.07% | readIniStringini_read.script:22
[P] [ 34]        17  0.07% | saveObjectToFilefs_io.script:41
[P] [ 35]        16  0.07% | ItemWeaponMagazined.script:41ItemWeaponMagazined.script:42
[P] [ 36]        15  0.06% | ItemPda.script:39ItemPda.script:40
[P] [ 37]        14  0.06% | configureObjectSchemesscheme_initialization.script:90
[P] [ 38]        14  0.06% | ZoneAnomalous.script:15ZoneAnomalous.script:17
[P] [ 39]        13  0.06% | bind.script:81bind.script:81
[P] [ 40]        13  0.06% | RestrictorBinder.script:117RestrictorBinder.script:118
[P] [ 41]        13  0.06% | UpgradesConfig.script:0UpgradesConfig.script:8
[P] [ 42]        13  0.06% | updateLevelDirectionTaskObject.script:279
[P] [ 43]        12  0.05% | bind.script:40bind.script:40
[P] [ 44]        12  0.05% | isBlackScreengame_check.script:15
[P] [ 45]        11  0.05% | SmartTerrain.script:277SmartTerrain.script:278
[P] [ 46]        11  0.05% | Stalker.script:110Stalker.script:111
[P] [ 47]        10  0.04% | ItemEatable.script:18ItemEatable.script:20
[P] [ 48]        10  0.04% | SmartTerrain.script:101SmartTerrain.script:102
[P] [ 49]        10  0.04% | HelmetBinder.script:46HelmetBinder.script:47
[P] [ 50]         9  0.04% | addRandomUpgradesupgrades_install.script:68
[P] [ 51]         9  0.04% | createTerrainJobsjob_create.script:62
[P] [ 52]         9  0.04% | isSimulationAvailableActor.script:111
[P] [ 53]         8  0.03% | ObjectPhysic.script:24ObjectPhysic.script:26
[P] [ 54]         8  0.03% | ActorBinder.script:212ActorBinder.script:213
[P] [ 55]         8  0.03% | Squad.script:317Squad.script:318
[P] [ 56]         8  0.03% | Stalker.script:33Stalker.script:35
[P] [ 57]         8  0.03% | updateSmartTerrain.script:391
[P] [ 58]         8  0.03% | SmartCover.script:81SmartCover.script:82
[P] [ 59]         8  0.03% | ZoneAnomalous.script:18ZoneAnomalous.script:19
[P] [ 60]         8  0.03% | SmartTerrainBinder.script:57SmartTerrainBinder.script:58
[P] [ 61]         8  0.03% | ItemWeaponMagazined.script:18ItemWeaponMagazined.script:20
[P] [ 62]         8  0.03% | SmartCover.script:27SmartCover.script:29
[P] [ 63]         8  0.03% | bind.script:80bind.script:80
[P] [ 64]         7  0.03% | ItemAmmo.script:18ItemAmmo.script:19
[P] [ 65]         7  0.03% | ItemAmmo.script:18ItemAmmo.script:20
[P] [ 66]         7  0.03% | ObjectHangingLamp.script:18ObjectHangingLamp.script:19
[P] [ 67]         7  0.03% | readFogDistancesweather_config.script:52
[P] [ 68]         7  0.03% | SmartTerrainBinder.script:57SmartTerrainBinder.script:61
[P] [ 69]         6  0.03% | createExclusiveJobjob_create_exclusive.script:43
[P] [ 70]         6  0.03% | infoLuaLogger.script:63
[P] [ 71]         6  0.03% | pickSectionFromCondListini_config.script:45
[P] [ 72]         6  0.03% | conditionobject.script:585
[P] [ 73]         6  0.03% | pickSectionFromCondListini_config.script:72
[P] [ 74]         6  0.03% | setupCallbacksPhysicObjectBinder.script:121
[P] [ 75]         6  0.03% | ItemWeaponMagazinedWGl.script:41ItemWeaponMagazinedWGl.script:42
[P] [ 76]         6  0.03% | Squad.script:268Squad.script:269
[P] [ 77]         6  0.03% | InventoryBox.script:18InventoryBox.script:19
[P] [ 78]         6  0.03% | onSendGenericNotificationNotificationManager.script:339
[P] [ 79]         5  0.02% | isObjectArrivedToTerrainsmart_terrain_object.script:52
[P] [ 80]         5  0.02% | bind.script:71bind.script:71
[P] [ 81]         5  0.02% | Monster.script:90Monster.script:91
[P] [ 82]         5  0.02% | [string]:0[string]:1
[P] [ 83]         5  0.02% | pickSectionFromCondListini_config.script:46
[P] [ 84]         5  0.02% | setupStalkerMotivationPlannersetup_motivation_planner.script:58
[P] [ 85]         5  0.02% | Stalker.script:53Stalker.script:55
[P] [ 86]         5  0.02% | ItemEatable.script:18ItemEatable.script:19
[P] [ 87]         4  0.02% | ItemGrenade.script:18ItemGrenade.script:19
[P] [ 88]         4  0.02% | ItemWeaponMagazinedWGl.script:18ItemWeaponMagazinedWGl.script:19
[P] [ 89]         4  0.02% | assignSimulationSquadToTerrainsimulation_squads.script:158
[P] [ 90]         4  0.02% | job_create.script:118job_create.script:118
[P] [ 91]         4  0.02% | ItemEatable.script:22ItemEatable.script:23
[P] [ 92]         4  0.02% | SmartTerrain.script:384SmartTerrain.script:385
[P] [ 93]         4  0.02% | MainMenu.script:317MainMenu.script:319
[P] [ 94]         4  0.02% | isJobAvailableToObjectjob_check.script:12
[P] [ 95]         4  0.02% | initializeSmartTerrain.script:433
[P] [ 96]         4  0.02% | isReachedBySimulationObjectSmartTerrain.script:665
[P] [ 97]         4  0.02% | conditionobject.script:579
[P] [ 98]         4  0.02% | ItemGrenade.script:39ItemGrenade.script:40
[P] [ 99]         4  0.02% | Monster.script:26Monster.script:27
[P] [100]         4  0.02% | parseConditionsListini_parse.script:180
[P] [101]         4  0.02% | interface.script:52interface.script:52
[P] [102]         4  0.02% | hasInfoPortioninfo_portion.script:55
[P] [103]         4  0.02% | object.script:0object.script:3
[P] [104]         4  0.02% | infoLuaLogger.script:50
[P] [105]         4  0.02% | PhysicalDoorManager.script:111PhysicalDoorManager.script:112
[P] [106]         4  0.02% | UpgradesConfig.script:0UpgradesConfig.script:7
[P] [107]         3  0.01% | setupStalkerMentalStatePlannermental_planner.script:18
[P] [108]         3  0.01% | spawnTreasureTreasureManager.script:171
[P] [109]         3  0.01% | createTerrainJobsjob_create.script:84
[P] [110]         3  0.01% | ActorBinder.script:123ActorBinder.script:125
[P] [111]         3  0.01% | AnomalyFieldBinder.script:21AnomalyFieldBinder.script:22
[P] [112]         3  0.01% | createStalkerPointJobsjob_create_stalker_point.script:29
[P] [113]         3  0.01% | registerObjectStoryLinksstory_objects.script:59
[P] [114]         3  0.01% | readIniBooleanini_read.script:111
[P] [115]         3  0.01% | parseInfoPortionsini_parse.script:24
[P] [116]         3  0.01% | Squad.script:171Squad.script:172
[P] [117]         3  0.01% | registerItemTreasureManager.script:239
[P] [118]         3  0.01% | getSquadMembersRelationToActorrelation_get.script:67
[P] [119]         3  0.01% | ItemExplosive.script:39ItemExplosive.script:40
[P] [120]         3  0.01% | isSquadArrivedToTerrainSmartTerrain.script:663
[P] [121]         3  0.01% | infoLuaLogger.script:58
[P] [122]         3  0.01% | ItemAmmo.script:22ItemAmmo.script:23
[P] [123]         3  0.01% | updateLevelDirectionTaskObject.script:277
[P] [124]         3  0.01% | updateSquadMapSpotmap_spot_squad.script:94
[P] [125]         3  0.01% | SurgeManager.script:0SurgeManager.script:3
[P] [126]         3  0.01% | setupStalkerMovementStatePlannermovement_planner.script:107
[P] [127]         3  0.01% | bind.script:72bind.script:72
[P] ==================================================================
[P] = Total samples: 23390
[P] = Total function calls duration: 23390 ms (approximate)
[P] ==================================================================

@Neloreck
Copy link
Contributor Author

Sampling profiler report example is above.
Going to add few console commands for profiler and open it for review.

Also I found out that we have tracy integration and tracy methods allow to track down specific zones. Will explore it as separate part in my project (I can try override AST nodes building from typescript to lua and add zones absolutely everywhere behind some building flag).

@Xottab-DUTY Xottab-DUTY mentioned this pull request Jan 18, 2025
4 tasks
@Neloreck Neloreck marked this pull request as ready for review January 19, 2025 01:42
@Neloreck Neloreck requested a review from Masterkatze as a code owner January 19, 2025 01:42
@Neloreck Neloreck requested a review from Xottab-DUTY January 19, 2025 01:45
@Neloreck
Copy link
Contributor Author

By the way, tracy zones idea worked. It crashes with admin mode bacause query backlog becomes bloated and tracy client starts requesting outdated pointers, but works fine in regular one.

image
image

Detected 2 hotspots with my typescript project:
1: Autosave on game start (expected, traced 1000+ atomic save operations)
image
2: Batched spawn of zombies for sawmill (traced to sounds init and loading of ogg files)
image

@Neloreck
Copy link
Contributor Author

@Xottab-DUTY
Will need patch for tracy lua methods to allow source inspection like in screenshot.
Seems like luaJIT is prefixing all paths with '@'?

Before:

static inline int LuaZoneBeginN( lua_State* L )
{
#if defined TRACY_HAS_CALLSTACK && defined TRACY_CALLSTACK
    return LuaZoneBeginNS( L );
#else
#ifdef TRACY_ON_DEMAND
    const auto zoneCnt = GetLuaZoneState().counter++;
    if( zoneCnt != 0 && !GetLuaZoneState().active ) return 0;
    GetLuaZoneState().active = GetProfiler().IsConnected();
    if( !GetLuaZoneState().active ) return 0;
#endif

    lua_Debug dbg;
    lua_getstack( L, 1, &dbg );
    lua_getinfo( L, "Snl", &dbg );
    size_t nsz;
    const auto name = lua_tolstring( L, 1, &nsz );
    const auto srcloc = Profiler::AllocSourceLocation( dbg.currentline, dbg.source && *dbg.source == '@' ? dbg.source + 1 : dbg.source, dbg.name ? dbg.name : dbg.short_src, name, nsz );

    TracyQueuePrepare( QueueType::ZoneBeginAllocSrcLoc );
    MemWrite( &item->zoneBegin.time, Profiler::GetTime() );
    MemWrite( &item->zoneBegin.srcloc, srcloc );
    TracyQueueCommit( zoneBeginThread );
    return 0;
#endif
}

After:


static inline int LuaZoneBeginN( lua_State* L )
{
#if defined TRACY_HAS_CALLSTACK && defined TRACY_CALLSTACK
    return LuaZoneBeginNS( L );
#else
#ifdef TRACY_ON_DEMAND
    const auto zoneCnt = GetLuaZoneState().counter++;
    if( zoneCnt != 0 && !GetLuaZoneState().active ) return 0;
    GetLuaZoneState().active = GetProfiler().IsConnected();
    if( !GetLuaZoneState().active ) return 0;
#endif

    lua_Debug dbg;
    lua_getstack( L, 1, &dbg );
    lua_getinfo( L, "Snl", &dbg );
    size_t nsz;
    const auto name = lua_tolstring( L, 1, &nsz );
    const auto srcloc = Profiler::AllocSourceLocation( dbg.currentline, dbg.source && *dbg.source == '@' ? dbg.source + 1 : dbg.source, dbg.name ? dbg.name : dbg.short_src, name, nsz );

    TracyQueuePrepare( QueueType::ZoneBeginAllocSrcLoc );
    MemWrite( &item->zoneBegin.time, Profiler::GetTime() );
    MemWrite( &item->zoneBegin.srcloc, srcloc );
    TracyQueueCommit( zoneBeginThread );
    return 0;
#endif
}

image

@Neloreck
Copy link
Contributor Author

@Xottab-DUTY Also seems like files naming is primary problem usage of blocking LUA code breakpoints (https://github.com/WheretIB/LuaDkmDebugger). With few line adjustments we can use them with openxray project.
Can share build / patch if needed.

image
image

@Xottab-DUTY
Copy link
Member

@Neloreck, is it ready for review/merge?

@Xottab-DUTY
Copy link
Member

@Xottab-DUTY Also seems like files naming is primary problem usage of blocking LUA code breakpoints (WheretIB/LuaDkmDebugger). With few line adjustments we can use them with openxray project. Can share build / patch if needed.

Can you send a PR to https://github.com/WheretIB/LuaDkmDebugger?

@Neloreck
Copy link
Contributor Author

Neloreck commented Feb 6, 2025

Yes, can be tested/reviewed

WheretIB/LuaDkmDebugger#26 -> can reopen, not sure about review time

@Neloreck
Copy link
Contributor Author

Neloreck commented Feb 6, 2025

@Xottab-DUTY Xottab-DUTY force-pushed the dev branch 3 times, most recently from c3ffa4d to 09b0b99 Compare March 6, 2025 15:34
1. Removed pch.hpp includes. Never include precompiled headers into
headers!
2. Moved luajit.h to script_profiler_portions.hpp because
xrScriptEngine.hpp is included globally, but we don't need LuaJIT
functions to be publicly available.
script_profiler.hpp include is removed from globally used
script_engine.hpp for that too.
@Xottab-DUTY Xottab-DUTY merged commit ac4ba75 into OpenXRay:dev Mar 18, 2025
32 of 33 checks passed
@github-project-automation github-project-automation bot moved this from In Progress to Done in Roadmap Mar 18, 2025
@Xottab-DUTY
Copy link
Member

Thanks so much!

@Xottab-DUTY
Copy link
Member

I have one question: why shared_str was used? Are there many string duplicates?

Ideally, we would like to minimize dynamic allocations as much as possible to minimize runtime overhead. Both shared_str and xr_string can allocate, so we would like to avoid using them. Is it possible?

@Neloreck
Copy link
Contributor Author

Which ones specifically? After another check I see that we can re-review part with constant values and remove dynamic str for profiler type etc. The biggest usage comes from profile-portions keys which are used as map keys and collected based on call trace

@joye-ramone
Copy link

joye-ramone commented Apr 1, 2025

@Neloreck can you provide more info about

(I can try override AST nodes building from typescript to lua and add zones absolutely everywhere behind some building flag).

I also using tracy for lua part, but marking zone in lua much more complicated compared to c++ because of missing automatic destruction of variables in lua

@Neloreck
Copy link
Contributor Author

Neloreck commented Apr 6, 2025

@joye-ramone
Since my codebase is entirely built with typescript link, I can add custom transformers via flag and inject tracy calls in every function.

You still can mark problematic places manually and add tracy marking, but you should add start zone and then attach zone end manually in all possible return clauses. If you miss some conditional return / else-if block you will get memory leak and crash of tracy/game

@Neloreck Neloreck deleted the dev-lua-profiler branch April 6, 2025 13:39
@joye-ramone
Copy link

very interesting solution... definity will take a look.
also I played for some time with both profiles.
for me sampling profiler mostly useless because of how lua code ingetraged with c++ logic...
but hook profiler looks very good!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Developer Experience Engine's programmer experience Enhancement Game assets A feature or an issue that involves gamedata change Lua Modmaker Experience Modmaker experience with OpenXRay SDK

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

3 participants