[WMCoolmon]

I decided to try profiling fs2_open today, and got some very interesting results. Note that all I did was:
1) Open Freespace 2
2) Hit enter at the pilot select screen
3) Enter the tech room
4) View the Ulysess, then the Ursa and the Artemis
5) Exited the tech room and clicked on "exit freespace" in the main screen

The one time I tried to start a mission the EXE crashed (results not included).

Without further ado, here are the upper portion of the results:

Code: [Select]

Profile: Function timing, sorted by time
Date:    Tue Feb 25 10:37:57 2003


Program Statistics
------------------
    Command line at 2003 Feb 25 10:35: "E:\games\freespace2\fs2_openprof"
    Total time: 58386.933 millisecond
    Time outside of functions: 74.180 millisecond
    Call depth: 41
    Total functions: 7161
    Total hits: 16566481
    Function coverage: 18.7%
    Overhead Calculated 651
    Overhead Average 651

Module Statistics for fs2_openprof.exe
--------------------------------------
    Time in module: 58312.754 millisecond
    Percent of time in module: 100.0%
    Functions in module: 7161
    Hits in module: 16566481
    Module function coverage: 18.7%

        Func          Func+Child           Hit
        Time   %         Time      %      Count  Function
---------------------------------------------------------
[b]   34952.687  59.9    35183.663  60.3      598 cf_find_file_location(char *,int,char *,int *,int *,bool) (cfilesystem.obj)[/b]
    9448.153  16.2    12395.027  21.3     1331 gr_d3d_bitmap_ex_internal(int,int,int,int,int,int) (grd3drender.obj)
    3220.170   5.5     3287.296   5.6     7915 stuff_float(float *) (parselo.obj)
    1719.930   2.9     1720.438   3.0       66 gr_d3d_restore_screen(int) (grd3d.obj)
    1639.834   2.8     1639.834   2.8  7725144 bm_set_components_argb_d3d_16_screen(unsigned char *,unsigned char *,unsigned char *,unsigned char *,unsigned char *) (bmpman.obj)
     914.829   1.6      914.829   1.6    16247 cfread(void *,int,int,struct CFILE *) (cfilearchive.obj)
     783.671   1.3      795.795   1.4      487 stuff_vector(struct vector *) (parselo.obj)
     538.610   0.9      538.610   0.9      365 gr_d3d_save_mouse_area(int,int,int,int) (grd3d.obj)
[b]     408.717   0.7    35535.437  60.9      599 cfopen(char *,char *,int,int,bool) (cfile.obj)[/b]
     360.866   0.6      360.866   0.6   126819 d3d_DrawPrimitive(enum _D3DPRIMITIVETYPE,enum _D3DVERTEXTYPE,void *,unsigned long,unsigned long) (grd3d.obj)
     336.389   0.6     1058.009   1.8  2557821 unpack_pixel(struct anim_instance *,unsigned char *,unsigned char,int,int) (packunpack.obj)
     329.583   0.6     4492.756   7.7       50 pcx_read_bitmap_16bpp(char *,unsigned char *) (pcxutils.obj)
     328.135   0.6     1717.954   2.9      179 unpack_frame(struct anim_instance *,unsigned char *,unsigned char *,int,unsigned char *,int,int) (packunpack.obj)
     251.780   0.4      260.069   0.4        1 psnet_init(int,int) (psnet2.obj)
     230.777   0.4      230.819   0.4    20789 cf_create_default_path_string(char *,int,char *,bool) (cfilesystem.obj)
     226.500   0.4      910.727   1.6  3195456 bm_24_to_16(int,unsigned short *) (bmpman.obj)
     206.741   0.4      206.813   0.4        2 gr_d3d_save_screen(void) (grd3d.obj)
     204.161   0.4      204.168   0.4        1 ds_init(int,int) (ds.obj)
     165.981   0.3      165.981   0.3    38234 diag_printf(char *,...) (parselo.obj)
     140.972   0.2      331.810   0.6   645409 unpack_pixel_count(struct anim_instance *,unsigned char *,unsigned char,int,int,int) (packunpack.obj)
     102.759   0.2      102.759   0.2   437611 bm_set_components_argb_d3d_16_tex(unsigned char *,unsigned char *,unsigned char *,unsigned char *,unsigned char *) (bmpman.obj)
     101.343   0.2      101.343   0.2      375 d3d_tcache_frame(void) (grd3dtexture.obj)
      87.322   0.1       87.399   0.1       11 gr_d3d_clear(void) (grd3drender.obj)
      83.461   0.1      804.030   1.4      375 gr_d3d_flip(void) (grd3d.obj)
      65.750   0.1       65.750   0.1       13 ds_load_buffer(int *,int *,int *,void *,struct sound_info *,int) (ds.obj)
      59.656   0.1      379.871   0.7   105032 gr_d3d_aabitmap_ex_internal(int,int,int,int,int,int) (grd3drender.obj)
      51.943   0.1      303.527   0.5        4 pcx_read_bitmap_8bpp(char *,unsigned char *,unsigned char *) (pcxutils.obj)
      49.914   0.1       49.914   0.1      555 cfclose(struct CFILE *) (cfile.obj)
      44.242   0.1       45.098   0.1       11 cf_search_root_pack(int) (cfilesystem.obj)
      39.500   0.1       39.500   0.1      162 debug_command::debug_command(char *,char *,void (*)(void)) (console.obj)
      38.416   0.1       38.416   0.1   184968 d3d_SetRenderState(enum _D3DRENDERSTATETYPE,unsigned long) (grd3d.obj)
[b]      35.724   0.1    26118.451  44.8      515 bm_load(char *) (bmpman.obj)[/b]
      35.120   0.1       35.127   0.1        9 d3d_create_texture_sub(int,int,unsigned short *,int,int,int,int,int,int,int,int,struct tcache_slot_d3d *,int,int) (grd3dtexture.obj)
      34.867   0.1     4835.348   8.3       54 bm_lock_pcx(int,int,struct bitmap_entry *,struct bitmap *,unsigned char,unsigned char) (bmpman.obj)
      32.267   0.1       35.211   0.1     5793 lcl_ext_localize(char *,char *,int,int *) (localize.obj)
      29.701   0.1       29.701   0.1   126370 bm_get_cache_slot(int,int) (bmpman.obj)
      27.437   0.0      273.962   0.5   126896 d3d_tcache_set(int,int,float *,float *,int,int,int,int) (grd3dtexture.obj)


Is it just me, or does cf_find_file_location seem like it's taking an absurd amount of time? I can post/upload the rest of the function information if needed.

[RandomTiger]

A ingame profile would be damn useful

[RandomTiger]

Are there any free or even demo profilers out there? I could really do with one.

[phreak]

run it through a mission or two and show us the results

[DTP]

Originally posted by WMCoolmon

Is it just me, or does cf_find_file_location seem like it's taking an absurd amount of time? I can post/upload the rest of the function information if needed.

Thats because those functions you highlight is accesing the hard-disk.

acces time to hard-disks is measured in Miliseconds,  rather than nano seconds as is the case with RAM.

if you know how, and you got the memory to do it.
try create a RAM-drive and install Freespace2 to it.

Those functions will dramaticly decrease their profile values.

Originally posted by PhReAk
run it through a mission or two and show us the results

Originally posted by WMCoolmon

The one time I tried to start a mission the EXE crashed (results not included).

[penguin]

cf_find_file_location probably does spend a lot of time doing stuff -- when files are opened, it looks for them on the disk, in VP files, etc.  And there are a lot of files, especially in the sparky* VP file.  IIRC, going into the tech room opens ships.tbl, parses it, then looks for all the POF files; as each POF is loaded, it's gotta find textures, etc.  And as DTP pointed out, disk access is slow compared to memory access.

The layout of the VP files is also not too optimal; an internal b-tree or something would be better, but that's a discussion for another day

BTW, this is also why mission loads take a while -- with debugging turned on, you can see it loading the POFs for all the ships in ships.tbl, even if they're not used in the mission.  (I think -- I remember noticing this a while ago, but haven't confirmed recently).

[Kazan]

$5 says it performs a linear search through the file list ... if it is smart enough to build a cache in memory of the file list

[DTP]

you got 5$, linear/lexiographical and yes it reads the list into memory.

It builds this list when you start fs2.

[penguin]

... so some sort of btree might improve performance, at least when starting missions.

Won't have any effect in-game, though.

[WMCoolmon]

Originally posted by DTP
you got 5$, linear/lexiographical and yes it reads the list into memory.

It builds this list when you start fs2.

Not a list of the files in the data directory, though. In the current build, fs2_open will attempt to open a file thirty-seven times - if I'm reading it correctly - before checking the VPs, for all the 500-some times find_file_location is called.

Removing that section of the code halves fs2_open's loading time.

It's a chunk of code that could be easily modified to be several times faster. I plan on performing said modifcations once 3.5 is released.

[Goober5000]

*bump*

Have said modifications been performed?

Does this have anything to do with your optimization routine that makes stuff run slower?

[WMCoolmon]

Yes, and if it's the thing causing the problem, yes. I just commited a command-line switch to CVS.