Allegro.cc - Online Community

Allegro.cc Forums » Programming Questions » Timing Allegro program sometimes... fails...

This thread is locked; no one can reply to it. rss feed Print
Timing Allegro program sometimes... fails...
Chris Katko
Member #1,881
January 2002
avatar

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.

-----sig:
“Programs should be written for people to read, and only incidentally for machines to execute.” - Structure and Interpretation of Computer Programs

Peter Hull
Member #1,136
March 2001

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

Edgar Reynaldo
Member #8,592
May 2007
avatar

Chris Katko
Member #1,881
January 2002
avatar

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 <iostream> 7 8#include <allegro5/allegro.h> 9#include <allegro5/allegro_font.h> 10#include <allegro5/allegro_image.h> 11#include <allegro5/allegro_color.h> 12#include <allegro5/allegro_primitives.h> 13#include <allegro5/allegro_ttf.h> 14#include <stdio.h> 15#include <stdarg.h> 16#include <math.h> 17 18#include "common.c" 19 20#include <list> 21#include <vector> 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...

-----sig:
“Programs should be written for people to read, and only incidentally for machines to execute.” - Structure and Interpretation of Computer Programs

Go to: