[Linux] GZDoom takes 12 seconds to start

[Sebelino]

I recently did a system upgrade where I removed Chocolate Doom and updated GZDoom among other things. After doing this, I noticed that it takes significantly longer for GZDoom to start up (roughly 2 seconds -> 12 seconds).

I captured the startup logs and an strace:

Code: Select all

$ strace -T -tt gzdoom -iwad ~/.config/gzdoom/doom2.wad +logfile TEMPLOG.txt 2> TEMP.txt

Code: Select all

$ cat TEMPLOG.txt
Log started: Sun May 13 12:01:36 2018

GZDoom version g3.3.2-m
M_LoadDefaults: Load system defaults.
W_Init: Init WADfiles.
 adding /usr/share/gzdoom/gzdoom.pk3, 684 lumps
 adding /usr/share/gzdoom/zd_extra.pk3, 132 lumps
 adding /home/sebelino/.config/gzdoom/doom2.wad, 2919 lumps
I_Init: Setting up machine state.
CPU Vendor ID: GenuineIntel
  Name: Intel(R) Core(TM) i7-3517U CPU @ 1.90GHz
  Family 6, Model 58, Stepping 9
  Features: SSE2 SSE3 SSSE3 SSE4.1 SSE4.2 HyperThreading
I_InitSound: Initializing OpenAL
  Opened device Built-in Audio Analog Stereo
  EFX enabled
V_Init: allocate screen.
S_Init: Setting up sound.
ST_Init: Init startup screen.
Checking cmd-line parameters...
S_InitData: Load sound definitions.
G_ParseMapInfo: Load map definitions.
Texman.Init: Init texture manager.
ParseTeamInfo: Load team definitions.
LoadActors: Load actor definitions.
script parsing took 367.49 ms
R_Init: Init Doom refresh subsystem.
DecalLibrary: Load decals.
M_Init: Init menus.
P_Init: Init Playloop state.
ParseSBarInfo: Loading custom status bar definition.
D_CheckNetGame: Checking network game status.
player 1 of 1 (1 nodes)
Using video driver x11
GL_VENDOR: Intel Open Source Technology Center
GL_RENDERER: Mesa DRI Intel(R) Ivybridge Mobile 
GL_VERSION: 4.2 (Core Profile) Mesa 18.0.3 (Core profile)
GL_SHADING_LANGUAGE_VERSION: 4.20
GL_EXTENSIONS: GL_3DFX_texture_compression_FXT1 GL_AMD_conservative_depth GL_AMD_draw_buffers_blend GL_AMD_seamless_cubemap_per_texture GL_AMD_shader_trinary_minmax GL_AMD_vertex_shader_layer GL_AMD_vertex_shader_viewport_index GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_APPLE_object_purgeable GL_ARB_ES2_compatibility GL_ARB_ES3_compatibility GL_ARB_arrays_of_arrays GL_ARB_base_instance GL_ARB_blend_func_extended GL_ARB_buffer_storage GL_ARB_clear_buffer_object GL_ARB_clear_texture GL_ARB_clip_control GL_ARB_compressed_texture_pixel_storage GL_ARB_compute_shader GL_ARB_conditional_render_inverted GL_ARB_conservative_depth GL_ARB_copy_buffer GL_ARB_copy_image GL_ARB_cull_distance GL_ARB_debug_output GL_ARB_depth_buffer_float GL_ARB_depth_clamp GL_ARB_derivative_control GL_ARB_direct_state_access GL_ARB_draw_buffers GL_ARB_draw_buffers_blend GL_ARB_draw_elements_base_vertex GL_ARB_draw_indirect GL_ARB_draw_instanced GL_ARB_enhanced_layouts GL_ARB_explicit_attrib_location GL_ARB_explicit_uniform_location GL_ARB_fragment_coord_conventions GL_ARB_fragment_layer_viewport GL_ARB_fragment_shader GL_ARB_framebuffer_no_attachments GL_ARB_framebuffer_object GL_ARB_framebuffer_sRGB GL_ARB_get_program_binary GL_ARB_get_texture_sub_image GL_ARB_gpu_shader5 GL_ARB_gpu_shader_fp64 GL_ARB_half_float_pixel GL_ARB_half_float_vertex GL_ARB_indirect_parameters GL_ARB_instanced_arrays GL_ARB_internalformat_query GL_ARB_internalformat_query2 GL_ARB_invalidate_subdata GL_ARB_map_buffer_alignment GL_ARB_map_buffer_range GL_ARB_multi_bind GL_ARB_multi_draw_indirect GL_ARB_occlusion_query2 GL_ARB_pipeline_statistics_query GL_ARB_pixel_buffer_object GL_ARB_point_sprite GL_ARB_polygon_offset_clamp GL_ARB_program_interface_query GL_ARB_provoking_vertex GL_ARB_robustness GL_ARB_sample_shading GL_ARB_sampler_objects GL_ARB_seamless_cube_map GL_ARB_seamless_cubemap_per_texture GL_ARB_separate_shader_objects GL_ARB_shader_atomic_counter_ops GL_ARB_shader_atomic_counters GL_ARB_shader_bit_encoding GL_ARB_shader_clock GL_ARB_shader_draw_parameters GL_ARB_shader_group_vote GL_ARB_shader_image_load_store GL_ARB_shader_image_size GL_ARB_shader_objects GL_ARB_shader_precision GL_ARB_shader_storage_buffer_object GL_ARB_shader_subroutine GL_ARB_shader_texture_image_samples GL_ARB_shader_texture_lod GL_ARB_shader_viewport_layer_array GL_ARB_shading_language_420pack GL_ARB_shading_language_packing GL_ARB_sync GL_ARB_tessellation_shader GL_ARB_texture_barrier GL_ARB_texture_buffer_object GL_ARB_texture_buffer_object_rgb32 GL_ARB_texture_buffer_range GL_ARB_texture_compression_bptc GL_ARB_texture_compression_rgtc GL_ARB_texture_cube_map_array GL_ARB_texture_filter_anisotropic GL_ARB_texture_float GL_ARB_texture_gather GL_ARB_texture_mirror_clamp_to_edge GL_ARB_texture_multisample GL_ARB_texture_non_power_of_two GL_ARB_texture_query_levels GL_ARB_texture_query_lod GL_ARB_texture_rectangle GL_ARB_texture_rg GL_ARB_texture_rgb10_a2ui GL_ARB_texture_storage GL_ARB_texture_storage_multisample GL_ARB_texture_swizzle GL_ARB_texture_view GL_ARB_timer_query GL_ARB_transform_feedback2 GL_ARB_transform_feedback3 GL_ARB_transform_feedback_instanced GL_ARB_transform_feedback_overflow_query GL_ARB_uniform_buffer_object GL_ARB_vertex_array_bgra GL_ARB_vertex_array_object GL_ARB_vertex_attrib_64bit GL_ARB_vertex_attrib_binding GL_ARB_vertex_shader GL_ARB_vertex_type_10f_11f_11f_rev GL_ARB_vertex_type_2_10_10_10_rev GL_ARB_viewport_array GL_ATI_blend_equation_separate GL_ATI_texture_float GL_EXT_abgr GL_EXT_blend_equation_separate GL_EXT_draw_buffers2 GL_EXT_draw_instanced GL_EXT_framebuffer_blit GL_EXT_framebuffer_multisample GL_EXT_framebuffer_multisample_blit_scaled GL_EXT_framebuffer_sRGB GL_EXT_packed_depth_stencil GL_EXT_packed_float GL_EXT_pixel_buffer_object GL_EXT_polygon_offset_clamp GL_EXT_provoking_vertex GL_EXT_shader_integer_mix GL_EXT_shader_samples_identical GL_EXT_texture_array GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_rgtc GL_EXT_texture_compression_s3tc GL_EXT_texture_filter_anisotropic GL_EXT_texture_integer GL_EXT_texture_sRGB GL_EXT_texture_sRGB_decode GL_EXT_texture_shared_exponent GL_EXT_texture_snorm GL_EXT_texture_swizzle GL_EXT_timer_query GL_EXT_transform_feedback GL_EXT_vertex_array_bgra GL_IBM_multimode_draw_arrays GL_INTEL_performance_query GL_KHR_blend_equation_advanced GL_KHR_context_flush_control GL_KHR_debug GL_KHR_no_error GL_KHR_robustness GL_MESA_pack_invert GL_MESA_shader_integer_functions GL_MESA_texture_signed_rgba GL_NV_conditional_render GL_NV_depth_clamp GL_NV_packed_depth_stencil GL_NV_texture_barrier GL_OES_EGL_image GL_S3_s3tc
Max. texture size: 16384
Max. texture units: 16
Max. varying: 128
Max. uniform block size: 65536
Uniform block alignment: 32
Resolution: 1920 x 1080

The ten-second delay occurs between the two final lines about uniform block alignment and resolution. From looking at the strace output, it seems loading gzdoom.pk3 is what takes time:

https://mega.nz/#!Z4Vm3TCb!f0OPHrRN-4j6 ... KYS3zEhxnA

Attaching my gzdoom.ini if that helps.

Code: Select all

$ uname -a
Linux Zenia 4.16.8-1-ARCH #1 SMP PREEMPT Wed May 9 11:25:02 UTC 2018 x86_64 GNU/Linux
$ cat /etc/os-release
NAME="Arch Linux"
PRETTY_NAME="Arch Linux"
ID=arch
ID_LIKE=archlinux
ANSI_COLOR="0;36"
HOME_URL="https://www.archlinux.org/"
SUPPORT_URL="https://bbs.archlinux.org/"
BUG_REPORT_URL="https://bugs.archlinux.org/"

[Graf Zahl]

I am not really surprised. Once, your system is a bit on the slow side, and second, does this driver feature shader caching? A complete recompile of all shaders takes a few seconds, if this has to be done for every launch, 12 seconds doesn't sound unreasonable with a 1.9 GHz CPU.

[Sebelino]

Thanks for the hint regarding shader caching! I upgraded mesa from 18.0.3 to 18.2.0 (by replacing extra/mesa with aur/mesa-git) and I now see that files were created in ~/.cache/mesa_shader_cache/ upon launch. The startup time is now back at 1-2 seconds.