[TUT] How to use an efficient debug system, which does not overload the final code

[Archive-Poster]

[Tutorial]
How to use an efficient debug system,
which do not overload your final code

Contents' Table
Introduction
Points
Gathering Everthing
Examples
Final Results
Credits

Notes
Frequently Asked Questions - FAQ
C/C++ Language Implementation

Introduction

Recently when developing plugins, was found a way to do a debug system that you do not need to delete after you configure it. This means that, if in the future you need to re-use you debug system, you do not need to re-create it, because it was never deleted. And was never deleted because you do not need to delete it, it is invisible to you final code and the Amx Mod X compiler itself, but not for its preprocessor.

Points
This debugging system is controlled by a preprocessor directive called 'IS_DEBUG_ENABLED'. This is how we declare it to our needs:

Code: Select all

/** This is to view internal program data while execution. See the function 'debugMesssageLogger(...)'
 * and the variable 'g_debug_level' for more information. Default value: 0  - which is disabled.
 */
#define IS_DEBUG_ENABLED 1

Once we declare it with the value 1, the preprocessor will understand that the debug system is active, then it will allow our Amx Mod X compiler to see our debugging code, i.e., compile it to our final binary file '.amxx'. But if the directive 'IS_DEBUG_ENABLED' is declared with the value 0, the preprocessor will understand that the debug system is inactive, then it will not allow our Amx Mod X compiler to see its code, i.e., compile it to our final binary file '.amxx'.

Now we define what will be our debug logger, that is controlled by our directive 'IS_DEBUG_ENABLED':

Code: Select all

#if IS_DEBUG_ENABLED > 0
    #define DEBUG_LOGGER(%1) debugMesssageLogger( %1 );

/**
 * ( 0 ) 0 disabled all debug.
 * ( 1 ) 1 displays basic debug messages.
 */
new g_debug_level = 1;
#else
    #define DEBUG_LOGGER(%1)
#endif

If the preprocessor directive 'IS_DEBUG_ENABLED' is declared as '1', i.e., active, we define that the preprocessor function DEBUG_LOGGER is to be recognized as our real debugger function 'debugMesssageLogger'. But if it is disabled, all debug functions at our code, will be recognized by the compiler as just a simple empty statement, which means that is like they never existed. See:
The choice for allow semicolons on Macros

Now let us see the printer function 'debugMesssageLogger', mentioned above, with outputs the debug messages to the console:

Code: Select all

#define LONG_STRING 256

/**
 * Write debug messages to server's console accordantly to the global variable g_debug_level.
 *
 * @param mode the debug mode level, see the variable 'g_debug_level' for the levels.
 * @param message[] the text formatting rules to display.
 * @param any the variable number of formatting parameters.
 */
stock debugMesssageLogger( mode, message[], any: ... )
{
    if( mode & g_debug_level )
    {
        static formated_message[ LONG_STRING ];
        
        vformat( formated_message, charsmax( formated_message ), message, 3 );
        
        server_print( "%s", formated_message         );
        client_print(       0, print_console,             "%s", formated_message );
    }
}

Gathering Everthing

So, gathering every thing mentioned until now, we get all we need to build are debug system. He it is the full code:

Code: Select all

#include <amxmodx>
#include <amxmisc>

#define LONG_STRING 256

/** This is to view internal program data while execution. See the function 'debugMesssageLogger(...)'
 * and the variable 'g_debug_level' for more information. Default value: 0  - which is disabled.
 */
#define IS_DEBUG_ENABLED 1 

#if IS_DEBUG_ENABLED > 0
    #define DEBUG_LOGGER(%1) debugMesssageLogger( %1 );

/**
 * ( 0 ) 0 disabled all debug.
 * ( 1 ) 1 displays basic debug messages.
 * ( 10 ) 2 displays leaving functions messages.
 * ( 100 ) 4 displays do_debug() messages.
 * ( 111 ) 7 displays all debug levels.
 */
new g_debug_level = 7;

/**
 * Write debug messages to server's console accordantly to the global variable g_debug_level.
 *
 * @param mode the debug mode level, see the variable 'g_debug_level' for the levels.
 * @param message[] the text formatting rules to display.
 * @param any the variable number of formatting parameters.
 */
stock debugMesssageLogger( mode, message[], any: ... )
{
    if( mode & g_debug_level )
    {
        static formated_message[ LONG_STRING ];
        
        vformat( formated_message, charsmax( formated_message ), message, 3 );
        
        server_print( "%s", formated_message         );
        client_print(       0, print_console,             "%s", formated_message );
    }
}
#else
    #define DEBUG_LOGGER(%1) 
#endif

/*
 * Called just after server activation.
 */
public plugin_init()
{
    DEBUG_LOGGER( 1,  "^n^nI am ENTERING on plugin_init()" )

    register_plugin( "Cool Plugin", "1.0", "Addons zz" );

    register_concmd( "amx_next", "do_debug" );

    do_debug();

    DEBUG_LOGGER( 2,  "I am LEAVING on plugin_init()^n" )
}

public do_debug()
{
    new hour;
    new minute;
    new second;
    
    time( hour, minute, second );

    DEBUG_LOGGER( 3,  "^nI am doing debug, the current time is: %d:%d:%d^n", \
            hour, minute, second )
}

This would out put this at the server/client console:

Code: Select all

I am ENTERING on plugin_init()

I am doing debug, the current time is: 19:55:12

I am LEAVING on plugin_init()

Examples
This function below integrates the mapchooser Galileo:

Code: Select all

stock client_print_color_internal( player_id, message[], any: ... )
{
    new formated_message[ COLOR_MESSAGE ];
    
    if( g_is_color_chat_supported )
    {
#if AMXX_VERSION_NUM < 183
        if( player_id )
        {
            vformat( formated_message, charsmax( formated_message ), message, 3 );
            DEBUG_LOGGER( 64, "( in ) Player_Id: %d, Chat printed: %s", player_id, formated_message )
            
            PRINT_COLORED_MESSAGE( player_id, formated_message )
        }
        else
        {
            new players_array[ 32 ];
            new players_number;
            
            get_players( players_array, players_number, "ch" );
            
            // Figure out if at least 1 player is connected
            // so we don't execute useless code
            if( !players_number )
            {
                DEBUG_LOGGER( 64, "!players_number. players_number = %d", players_number )
                return;
            }
            
            new player_id;
            new string_index;
            new argument_index;
            new multi_lingual_constants_number;
            
            new params_number                     = numargs();
            new Array:multi_lingual_indexes_array = ArrayCreate();
            
            DEBUG_LOGGER( 64, "players_number: %d, params_number: %d", players_number, params_number )
            
            if( params_number >= 4 ) // ML can be used
            {
                for( argument_index = 2; argument_index < params_number; argument_index++ )
                {
                    DEBUG_LOGGER( 64, "argument_index: %d, getarg(argument_index): %d / %s", \
                            argument_index, getarg( argument_index ), getarg( argument_index ) )
                    
                    // retrieve original param value and check if it's LANG_PLAYER value
                    if( getarg( argument_index ) == LANG_PLAYER )
                    {
                        string_index = 0;
                        
                        // as LANG_PLAYER == -1, check if next param string is a registered language translation
                        while( ( formated_message[ string_index ] =
                                     getarg( argument_index + 1, string_index++ ) ) )
                        {
                        }
                        formated_message[ string_index ] = 0;
                        
                        DEBUG_LOGGER( 64, "Player_Id: %d, formated_message: %s, \
                                GetLangTransKey( formated_message ) != TransKey_Bad: %d", \
                                player_id, formated_message, \
                                GetLangTransKey( formated_message ) != TransKey_Bad )
                        
                        DEBUG_LOGGER( 64, "(multi_lingual_constants_number: %d, string_index: %d", \
                                multi_lingual_constants_number, string_index )
                        
                        if( GetLangTransKey( formated_message ) != TransKey_Bad )
                        {
                            // Store that argument as LANG_PLAYER so we can alter it later
                            ArrayPushCell( multi_lingual_indexes_array, argument_index++ );
                            
                            // Update ML array, so we'll know 1st if ML is used,
                            // 2nd how many arguments we have to change
                            multi_lingual_constants_number++;
                        }
                        
                        DEBUG_LOGGER( 64, "argument_index (after ArrayPushCell): %d", argument_index )
                    }
                }
            }
            
            DEBUG_LOGGER( 64, "(multi_lingual_constants_number: %d", multi_lingual_constants_number )
            
            for( --players_number; players_number >= 0; players_number-- )
            {
                player_id = players_array[ players_number ];
                
                if( multi_lingual_constants_number )
                {
                    for( argument_index = 0; argument_index < multi_lingual_constants_number; argument_index++ )
                    {
                        // Set all LANG_PLAYER args to player index ( = player_id )
                        // so we can format the text for that specific player
                        setarg( ArrayGetCell( multi_lingual_indexes_array, argument_index ), _, player_id );
                        
                        DEBUG_LOGGER( 64, "(argument_index: %d, player_id: %d, \
                                ArrayGetCell( multi_lingual_indexes_array, argument_index ): %d", \
                                argument_index, player_id, \
                                ArrayGetCell( multi_lingual_indexes_array, argument_index ) )
                    }
                    vformat( formated_message, charsmax( formated_message ), message, 3 );
                }
                
                DEBUG_LOGGER( 64, "( in ) Player_Id: %d, Chat printed: %s", player_id, formated_message )
                PRINT_COLORED_MESSAGE( player_id, formated_message )
            }
            
            ArrayDestroy( multi_lingual_indexes_array );
        }
#else
        vformat( formated_message, charsmax( formated_message ), message, 3 );
        DEBUG_LOGGER( 64, "( in ) Player_Id: %d, Chat printed: %s", player_id, formated_message )
        
        client_print_color( player_id, print_team_default, formated_message );
#endif
    }
    else
    {
        vformat( formated_message, charsmax( formated_message ), message, 3 );
        DEBUG_LOGGER( 64, "( in ) Player_Id: %d, Chat printed: %s", player_id, formated_message )
        
        REMOVE_COLOR_TAGS( formated_message )
        client_print( player_id, print_chat, formated_message );
    }
    DEBUG_LOGGER( 64, "( out ) Player_Id: %d, Chat printed: %s", player_id, formated_message )
}

Here is the output example:

Code: Select all

players_number: 1, params_number: 4
argument_index: 2, getarg(argument_index): -1 / 
Player_Id: 0, formated_message: GAL_CHANGE_TIMEEXPIRED, GetLangTransKey( formated_message ) != TransKey_Bad = 1
(multi_lingual_constants_number: 0, string_index: 23
argument_index: 3
(multi_lingual_constants_number: 1
(argument_index: 0, player_id: 4, ArrayGetCell( multi_lingual_indexes_array, argument_index ): 2
( in ) Player_Id: 4, Chat printed: O Limite de Tempo expirou.
( out ) Player_Id: 0, Chat printed: O Limite de Tempo expirou.

At that code you can see the use of the 'DEBUG_LOGGER' directive. Here below are the currently active debug levels at that plugin

Code: Select all

#if IS_DEBUG_ENABLED > 0
    #define DEBUG_LOGGER(%1) debugMesssageLogger( %1 );

/**
 * ( 0 ) 0 disabled all debug.
 * ( 1 ) 1 displays basic debug messages.
 * ( 10 ) 2 displays players disconnect, total number, multiple time limits changes and restores.
 * ( 100 ) 4 displays maps events, choices, votes, nominations, and the calls to 'map_populateList'.
 * ( ... ) 8 displays vote_loadChoices( ) and actions at vote_startDirector.
 * ( ... ) 16 displays messages related to RunOff voting.
 * ( ... ) 32 displays messages related to the rounds end map voting.
 * ( ... ) 64 displays messages related 'client_print_color_internal'.
 * ( ... ) 128 execute the test units and print their out put results.
 * ( 11111111 ) 255 displays all debug logs levels at server console.
 */
new g_debug_level 251

#else
    #define DEBUG_LOGGER(%1)
#endif

One tip, is that you some times need to print something that is really big and do not fit to any debug levels you already have, or you do not want to create a debug level just for it. So you declare is as debug level 1 to see it, a during the time you need, and when you do not need it anymore, change its level to 0. That level means that it will never be showed at any level, just when you go to it, and change it to an accept level as 1. For exemple, when was needed to know if all my maps was being loaded and how are they being loaded from the map directory, at the moment the nomination menu was showed. Hence, to do that was just created a debug logger with level 1 while it was needed it, and later, it was placed it to the level 0, because there are a lot of maps at the map directory, and as each one of them are being printed in one line, have it enabled at any debug level is annoying. This is the code:

Code: Select all

stock nomination_menu( player_id )
{
    // assume there'll be more than one match ( because we're lazy ) and starting building the match menu
    if( g_nominationMatchesMenu[ player_id ] )
    {
        menu_destroy( g_nominationMatchesMenu[ player_id ] );
    }
    
    g_nominationMatchesMenu[ player_id ] = menu_create( "Nominate Map", "nomination_handleMatchChoice" );
    
    // gather all maps that match the nomination
    new mapIdx;
    
    new info[ 1 ];
    new choice[ 64 ];
    new nominationMap[ 32 ];
    new disabledReason[ 16 ];
    
    for( mapIdx = 0; mapIdx < g_nominationMapCnt; mapIdx++ )
    {
        ArrayGetString( g_nominationMap, mapIdx, nominationMap, charsmax( nominationMap ) );
        
        info[ 0 ] = mapIdx;
        
        // in most cases, the map will be available for selection, so assume that's the case here
        disabledReason[ 0 ] = '^0';
        
        if( nomination_getPlayer( mapIdx ) ) // disable if the map has already been nominated
        {
            formatex( disabledReason, charsmax( disabledReason ), "%L", player_id,
                    "GAL_MATCH_NOMINATED" );
        }
        else if( map_isTooRecent( nominationMap ) ) // disable if the map is too recent
        {
            formatex( disabledReason, charsmax( disabledReason ), "%L", player_id,
                    "GAL_MATCH_TOORECENT" );
        }
        else if( equal( g_currentMap, nominationMap ) ) // disable if the map is the current map
        {
            formatex( disabledReason, charsmax( disabledReason ), "%L", player_id,
                    "GAL_MATCH_CURRENTMAP" );
        }
        
        formatex( choice, charsmax( choice ), "%s %s", nominationMap, disabledReason );
        
        menu_additem( g_nominationMatchesMenu[ player_id ], choice, info,
                ( disabledReason[ 0 ] == '^0' ? 0 : ( 1 << 26 ) ) );
        
        DEBUG_LOGGER( 0, "( nomination_menu ) choice: %s, info[0]: %d", choice, info[ 0 ] )
    }
    
    menu_display( player_id, g_nominationMatchesMenu[ player_id ] );
}

Here is the output example, when the debug level other than 0, i.e., is activated:

Code: Select all

( nomination_menu ) choice: !!!sex_movie , info[0]: 0
( nomination_menu ) choice: !!water_iceworld , info[0]: 1
( nomination_menu ) choice: !!_STTZ_!! , info[0]: 2
( nomination_menu ) choice: !!~sex_movie , info[0]: 3
( nomination_menu ) choice: !3 , info[0]: 4
( nomination_menu ) choice: !vip_truck , info[0]: 5
...
...
...
( nomination_menu ) choice: zm_toxic_house2 , info[0]: 802
( nomination_menu ) choice: zm_uknow , info[0]: 803
( nomination_menu ) choice: zm_uknow_last_hope , info[0]: 804
( nomination_menu ) choice: zm_umbrella_v1 , info[0]: 805
( nomination_menu ) choice: zm_zombattack , info[0]: 806
( nomination_menu ) choice: zm_zombies , info[0]: 807
( cmd_say ) equali( arg1, 'nom', 3 ): 1, equali( arg1[ strlen( arg1 ) - 4 ], 'menu' ): 1
[V]iper*S| Addons zz : nomenu
L 01/11/2016 - 16:38:32: "[V]iper*S| Addons zz<1><STEAM_ID_LAN><CT>" say "nomenu"

You can also protect a whole code block, then sometimes just the 'DEBUG_LOGGER' directives are not enough. This is an example using the IS_DEBUG_ENABLED protection:

Code: Select all

/**
 * Loads the config file "voting_list.ini" and all mods stored there.
 */
public load_votingList()
{
    new currentLine         [ LONG_STRING ];
    new currentLine_splited [ SHORT_STRING ];
    new mod_name            [ SHORT_STRING ];
    new mod_shortName_string[ SHORT_STRING ];
    new unusedLast_string   [ SHORT_STRING ];
    
    new votingList_filePointer = fopen( g_votingList_filePath, "rt" );
    
    while( !feof( votingList_filePointer ) )
    {
        fgets( votingList_filePointer, currentLine, charsmax( currentLine ) );
        trim( currentLine );
        
        // skip commentaries while reading file
        if( !currentLine[ 0 ]
            || currentLine[ 0 ] == ';'
            || ( currentLine[ 0 ] == '/'
                 && currentLine[ 1 ] == '/' ) )
        {
            continue;
        }
        
        if( currentLine[ 0 ] == '[' )
        {
            g_modCounter++
            
            // remove line delimiters [ and ]
            replace_all( currentLine, charsmax( currentLine ), "[", "" );
            replace_all( currentLine, charsmax( currentLine ), "]", "" );
            
            // broke the current config line, in modname ( mod_name ), modtag ( mod_shortName_string )
            strtok( currentLine, mod_name, charsmax( mod_name ), currentLine_splited, charsmax( currentLine_splited ), ':', 0 );
            strtok( currentLine_splited, mod_shortName_string, charsmax( mod_shortName_string ), unusedLast_string,
                    charsmax( unusedLast_string ), ':', 0 );
            
            // stores at memory the modname and the modShortName
            formatex( g_mod_names[ g_modCounter ], sizeof( g_mod_names[] ) - 1, "%s", mod_name );
            formatex( g_mod_shortNames[ g_modCounter ], sizeof( g_mod_shortNames[] ) - 1, "%s", mod_shortName_string );
            
            DEBUG_LOGGER( 1, "[AMX MOD Loaded] %d - %s",  g_modCounter - 2, g_mod_names[ g_modCounter ] )
        
        #if IS_DEBUG_ENABLED > 0
            if( g_debug_level & 2 )
            {
                new mapcycle_filePath       [ SHORT_STRING ];
                new config_filePath         [ SHORT_STRING ];
                new plugin_filePath         [ SHORT_STRING ];
                new message_filePath        [ SHORT_STRING ];
                new messageResource_filePath[ SHORT_STRING ];
                new lateConfig_filePath     [ SHORT_STRING ];
                
                mapcycle_pathCoder( mod_shortName_string, mapcycle_filePath, charsmax( mapcycle_filePath ) );
                config_pathCoder( mod_shortName_string, config_filePath, charsmax( config_filePath ) );
                plugin_pathCoder( mod_shortName_string, plugin_filePath, charsmax( plugin_filePath ) );
                message_pathCoder( mod_shortName_string, message_filePath, charsmax( message_filePath ) );
                
                messageResource_pathCoder( mod_shortName_string, messageResource_filePath,
                        charsmax( messageResource_filePath ) );
                
                lateConfig_pathCoder( mod_shortName_string, lateConfig_filePath, charsmax( lateConfig_filePath ) );
                
                server_print( "[AMX MOD Loaded] %s", mod_shortName_string );
                server_print( "[AMX MOD Loaded] %s", mapcycle_filePath );
                server_print( "[AMX MOD Loaded] %s", plugin_filePath );
                server_print( "[AMX MOD Loaded] %s", config_filePath );
                server_print( "[AMX MOD Loaded] %s", message_filePath );
                server_print( "[AMX MOD Loaded] %s", lateConfig_filePath );
                server_print( "[AMX MOD Loaded] %s^n", messageResource_filePath );
            }
        #endif
        }
    }
    fclose( votingList_filePointer )
}

Here is the output example:

Code: Select all

[AMX MOD Loaded] 1 - CS-DM (DeathMatch)
[AMX MOD Loaded] csdm
[AMX MOD Loaded] mapcycles/csdm.txt
[AMX MOD Loaded] addons/amxmodx/configs/multimod/plugins/csdm.ini
[AMX MOD Loaded] addons/amxmodx/configs/multimod/cfg/csdm.cfg
[AMX MOD Loaded] addons/amxmodx/configs/multimod/msg/csdm.cfg
[AMX MOD Loaded] addons/amxmodx/configs/multimod/latecfg/csdm.cfg
[AMX MOD Loaded] addons/amxmodx/configs/multimod/csdm.cfg
...
...
...
[AMX MOD Loaded] 13 - Zombie Mod with AmmoPacks
[AMX MOD Loaded] zp50Ammo
[AMX MOD Loaded] mapcycles/zp50Ammo.txt
[AMX MOD Loaded] addons/amxmodx/configs/multimod/plugins/zp50Ammo.ini
[AMX MOD Loaded] addons/amxmodx/configs/multimod/cfg/zp50Ammo.cfg
[AMX MOD Loaded] addons/amxmodx/configs/multimod/msg/zp50Ammo.cfg
[AMX MOD Loaded] addons/amxmodx/configs/multimod/latecfg/zp50Ammo.cfg
[AMX MOD Loaded] addons/amxmodx/configs/multimod/zp50Ammo.cfg

Final Results

Now, let show that the 'DEBUG_LOGGER' directives are really working and doing the job to keep the final compiled binary '.amxx' clean of debug statements. Here is a table containing at a relation between the mapchooser Galileo with its 'IS_DEBUG_ENABLED' directive activated, and deactivated.

Compilations data comparisons at the Amx Mod X "1.8.3-dev+4964"

Code: Select all

Plugin name:   IS_DEBUG_ENABLED 0     IS_DEBUG_ENABLED 1       Diferences
Header size:           3.532 bytes           3.860 bytes       + 328 bytes
Code size:            70.936 bytes          87.104 bytes     +16.168 bytes
Data size:            42.680 bytes          67.996 bytes     +25.316 bytes
Stack/heap size:      16.384 bytes          16.384 bytes        +0.0 bytes
Total requirements:  133.532 bytes         175.344 bytes     +41.812 bytes
Compilation Time:       0,47 sec              0,55 sec

Source data

Code: Select all

//AMXXPC compile.exe
// by the AMX Mod X Dev Team


//// galileo0.sma
// 
// Header size:           3532 bytes
// Code size:            70936 bytes
// Data size:            42680 bytes
// Stack/heap size:      16384 bytes
// Total requirements:  133532 bytes
// Done.
//
// Compilation Time: 0,47 sec
// ----------------------------------------

//// galileo1.sma
// 
// Header size:           3860 bytes
// Code size:            87104 bytes
// Data size:            67996 bytes
// Stack/heap size:      16384 bytes
// Total requirements:  175344 bytes
// Done.
//
// Compilation Time: 0,55 sec
// ----------------------------------------

Press enter to exit ...