Timing Allegro program sometimes... fails...

no-reply@allegro.cc (Chris Katko) — Sun, 11 Jun 2017 11:10:39 +0000

I wanted to benchmark blitting various size textures to the screen.

Either
- Draws per second (requiring FPS timing)
- Seconds per X draws (simply run X blits and time the program's execution.)

I ran into an issue with the first method. Since Allegro is using an event structure but is "essentially" single-threaded, I could "fire off" an event that says "one second has passed" but the problem is... how do you TERMINATE an existing job? The job itself would run (say blitting for 1/2 second) and only when that job (a function, really) is finished its for loop, can the event actually be processed.

I kept trying to get that to work but failing (perhaps I just have a mental block for the simple solution). So I fell back on the second method. Simply draw 30000 blits of a specific texture size and time it using Linux/bash's time command.

But here's the problem, and I'm considering making a StackOverflow post about it but I couldn't find ANYONE with the problem.

SOMETIMES, when I run:

 $ time ./myprogram

It'll be 5-10 seconds. Other times with the same program it'll report close to .5 seconds which is FAR lower than it actually is. Almost like it's timing a thread other than the main thread, and that other thread is just idling.

Here's the actual output:

#SelectExpand
  1$ time ./speedtest
  2
  3[init] Start up.
  4Maximum texture size reported to Allegro is 8192
  5WARNING - Size 16384^2 is a MEMORY BITMAP! 
  6[init] End.
  7[execute] Start up.
  8[execute] End.
  9[shutdown] Start up.
 10[shutdown] End.
 11
 12real  0m0.919s //<------- WRONG
 13user  0m0.544s
 14sys  0m0.244s
 15
 16$ time ./speedtest
 17[init] Start up.
 18Maximum texture size reported to Allegro is 8192
 19WARNING - Size 16384^2 is a MEMORY BITMAP! 
 20[init] End.
 21[execute] Start up.
 22[execute] End.
 23[shutdown] Start up.
 24[shutdown] End.
 25
 26real  0m20.332s //<-------- Actual
 27user  0m0.564s
 28sys  0m0.192s

And even then, when I had lower draw call numbers and it was faster, time still felt like it slightly under-reported every time. I would sit there, watch the command that I triggered, and I would feel like it was 5 seconds and it would tell me... ~2.3. And I am NOT that bad at counting seconds. But it's possible I just miscalculated something. What's NOT possible is my program magically goes from 20 seconds ... to .5 seconds.

I have tried both bash's "time" ($ time ./myprogram) as well as the (POSIX?) /usr/bin/time . Both report the same values as far as I can tell.

My only thought is that Allegro is running multiple threads and time is reporting the wrong one.

no-reply@allegro.cc (Peter Hull) — Tue, 13 Jun 2017 14:37:01 +0000

As I understand it, time measures the process, so the number of threads should not give a false result.
Are you saying the prompt does not return for 20 seconds but it still reports 0.5 seconds?
The only thing I can suggest is using the -v flag to /usr/bin/time or maybe investigate the perf command - they might give you some insight on why some runs are different.

Pete

no-reply@allegro.cc (Edgar Reynaldo) — Tue, 13 Jun 2017 19:21:27 +0000

al_get_time. Don't know what the implementation is on linux, but it should have resolution on the order of milliseconds at least.

no-reply@allegro.cc (Chris Katko) — Tue, 13 Jun 2017 19:33:40 +0000

I just timed it... on video... with my phone. 11 seconds, yet time reports 1.x seconds. Like it's off by a factor of 10x.

Try it yourself!

#SelectExpand
   1// Completely hobbled together code. It wasn't meant to be elegant, just to test some speeds.
   2// You'll need the 'common.c' from the Allegro examples folder.
   3
   4#define ALLEGRO_STATICLINK
   5
   6#include 
   7
   8#include 
   9#include 
  10#include 
  11#include 
  12#include 
  13#include 
  14#include 
  15#include 
  16#include 
  17
  18#include "common.c"
  19
  20#include 
  21#include 
  22
  23namespace g
  24  {
  25  const int SCREEN_W = 640;
  26  const int SCREEN_H = 480;
  27
  28     ALLEGRO_DISPLAY *display;
  29     ALLEGRO_TIMER *timer;
  30     ALLEGRO_TIMER *fps_timer;
  31  ALLEGRO_EVENT_QUEUE *queue;
  32  ALLEGRO_FONT *font;
  33  const float LOGIC_FPS = 60;
  34  
  35  //framerate time keeping
  36  int frames_passed = 0;   
  37  int fps = 0;
  38  
  39  
  40  ALLEGRO_BITMAP *current_screen;
  41  ALLEGRO_BITMAP *fake_map;
  42  };
  43
  44using namespace g;
  45using namespace std;
  46
  47//forward declarations
  48class map_chunk_t;
  49class guessing_algorithm_t;
  50
  51enum MYKEYS {
  52   KEY_UP, KEY_DOWN, KEY_LEFT, KEY_RIGHT,
  53   KEY_W, KEY_S, KEY_A, KEY_D, KEY_C, KEY_P
  54};
  55
  56int number_of_draws_per_second = 0;
  57int number_of_draws = 0;
  58ALLEGRO_BITMAP *test_blit_512;
  59ALLEGRO_BITMAP *test_blit_1024;
  60ALLEGRO_BITMAP *test_blit_2048;
  61ALLEGRO_BITMAP *test_blit_4096;
  62ALLEGRO_BITMAP *test_blit_8192;
  63ALLEGRO_BITMAP *test_blit_16384;
  64
  65void run_test(int size, int count)
  66  {
  67  ALLEGRO_BITMAP *source;
  68  
  69  if(size == 512){source = test_blit_512;}
  70  if(size == 1024){source = test_blit_1024;}
  71  if(size == 2048){source = test_blit_2048;}
  72  if(size == 4096){source = test_blit_4096;}
  73  if(size == 8192){source = test_blit_8192;}
  74  if(size == 16384){source = test_blit_16384;}
  75  
  76  for(int i = 0; i < count; i++)
  77    {
  78    al_draw_bitmap(source, rand()%320, rand()%240, 0);
  79    number_of_draws++;
  80    }
  81  
  82
  83  }
  84
  85int initialize()
  86  {
  87
  88  if (!al_init()) {
  89    abort_example("Could not init Allegro.\n");
  90  }
  91
  92  al_install_keyboard();
  93  al_install_mouse();
  94  al_init_image_addon();
  95  al_init_font_addon();
  96  al_init_ttf_addon();
  97  init_platform_specific();
  98
  99  g::display = al_create_display(800, 600);
 100  if (!g::display) {
 101    abort_example("Error creating display\n");
 102    }
 103   
 104  timer = al_create_timer(1.0 / g::LOGIC_FPS);
 105  fps_timer = al_create_timer(1.0);
 106
 107  g::queue = al_create_event_queue();
 108  al_register_event_source(g::queue, al_get_keyboard_event_source());
 109  al_register_event_source(g::queue, al_get_mouse_event_source());
 110  al_register_event_source(g::queue, al_get_display_event_source(display));
 111  al_register_event_source(g::queue, al_get_timer_event_source(timer));
 112  al_register_event_source(g::queue, al_get_timer_event_source(fps_timer));
 113
 114  al_start_timer(g::timer);
 115  al_start_timer(g::fps_timer);
 116
 117  g::font = al_load_font("DejaVuSans.ttf", 16, 0);
 118  if(g::font == NULL)printf("OH SHIT FONT NOT FOUND OR FAILED TO LOAD.\n");
 119
 120// PNGS and JPEGS are tested to work.
 121//  fake_map = al_load_bitmap("./maps/SecretofMana_map_gaiasnavel.png");
 122  fake_map = al_load_bitmap("./maps/EarthboundMapDustyDunesDesert.png");
 123  current_screen = al_create_bitmap(320, 200); //= al_load_bitmap("screen_view.png");
 124
 125  test_blit_512 = al_create_bitmap(512, 512);
 126  test_blit_1024 = al_create_bitmap(1024, 1024);
 127  test_blit_2048 = al_create_bitmap(2048, 2048);
 128  test_blit_4096 = al_create_bitmap(4096, 4096);
 129  test_blit_8192 = al_create_bitmap(8192, 8192);
 130  test_blit_16384 = al_create_bitmap(16384, 16384);
 131  
 132  
 133  int MAX_TEX = al_get_display_option(g::display, ALLEGRO_MAX_BITMAP_SIZE);
 134  printf("Maximum texture size reported to Allegro is %i\n", MAX_TEX);
 135
 136
 137  if(test_blit_4096 == NULL){printf("Can't make a 4096x4096 bitmap.\n");}
 138  if(test_blit_8192 == NULL){printf("Can't make a 8192x8192 bitmap.\n");}
 139  if(test_blit_16384 == NULL){printf("Can't make a 16384x16384 bitmap.\n");}
 140
 141
 142  int x;
 143  if((x = al_get_bitmap_flags(test_blit_2048)) & ALLEGRO_MEMORY_BITMAP)
 144    {
 145    printf("WARNING - Size 2048^2 is a MEMORY BITMAP! \n");
 146    }
 147  if((x = al_get_bitmap_flags(test_blit_4096)) & ALLEGRO_MEMORY_BITMAP)
 148    {
 149    printf("WARNING - Size 4096^2 is a MEMORY BITMAP! \n");
 150    }
 151  if((x = al_get_bitmap_flags(test_blit_8192)) & ALLEGRO_MEMORY_BITMAP)
 152    {
 153    printf("WARNING - Size 8192^2 is a MEMORY BITMAP! \n");
 154    }
 155  if((x = al_get_bitmap_flags(test_blit_16384)) & ALLEGRO_MEMORY_BITMAP)
 156    {
 157    printf("WARNING - Size 16384^2 is a MEMORY BITMAP! \n");
 158    }
 159  
 160  return 0;
 161  }
 162
 163void shutdown()
 164  {
 165  al_destroy_event_queue(g::queue);  
 166  }
 167
 168void execute2()
 169  {
 170  run_test(1024, 30000);
 171  }
 172
 173int main(int argc, char **argv)
 174  {
 175  cout << "[init] Start up." << endl;
 176  initialize();
 177  cout << "[init] End." << endl;
 178  cout << "[execute] Start up." << endl;
 179
 180
 181 execute2();
 182
 183
 184  cout << "[execute] End." << endl;
 185  cout << "[shutdown] Start up." << endl;
 186  shutdown();
 187  cout << "[shutdown] End." << endl;
 188  return 0;
 189  }

And the build file--though yours should work fine. For some reason I've always had problems doing it the "proper" way with the package config utility on this laptop.

#SelectExpand
  1clang++ speedtest.cpp -o speedtest -fcolor-diagnostics  -O3  \
  2-I/usr/local/include/**   \
  3-I/usr/local/include/allegro5/**   \
  4-lallegro_monolith-static   \
  5-lpthread  \
  6-lGL \
  7-lGLU \
  8-lXcursor \
  9-lXi \
 10-lXrandr \
 11-lX11 \
 12-lXinerama \
 13-lz \
 14-lpng \
 15-ljpeg  \
 16-lfreetype

FYI, I imagine I can time it other ways like with the internal allegro timer. My question here is because I've only seen it do this with my Allegro program(s) and I couldn't find a SO answer even remotely describing the problem. Perhaps I'll ask on Stack Overflow after all...