Ideas / best practices for controlling verbosity in matlab functions

Question

Let's say I have some_fun that does some complicated work.

function foo = some_complicated_fun(x,y,z,verbosity)

I've written a good bit of debugging prints into this code, but the avg user may not be interested in seeing all that if it is working. Error statements (not enough args, etc) will print regardless.

My current method for writing a function is:

function foo = some_complicated_fun(x,y,z,verbosity)

(x,y,z,verbosity) = parse_args(x,y,z,verbosity); % parse args, check nargin, etc

for i=1:5, 

    % whatever    
    % do some work with x,y,z
    % blah blah

    if verbosity 
        fprintf('Now on iteration %i\n',i); % basic print
    end

    % or, with mutiple levels:
    if verbosity == 1;
        fprintf('Now on iteration %i\n',i); % basic print
    end
    if verbosity == 2;
        fprintf('x = %f,y = %f,z=%f %i\n',x,y,z); % more information
    end

    % do more work

end

I don't like doing it with the if statements because it clutters up the code, but I can't think of any other way. A one liner is better and worse:

if verbosity; fprintf('Iteration %i\n',i); end

Better because it's smaller, worse because one-liners are less readable than the same thing over 3 lines.

What I want is some simple, more elegant way to control verbosity.

Does that exist?

Goddamned

Answer 1

I have created a method to control log output verbosity. It is not finished yet, but since this question appeared I uploaded it to:

This link at Matlab File Exchange.

It works by setting global output log to the desired level, and will show the message on the following format:

OUTPUT_LEVEL:  function_which_called_message       Your_Message.

However, it will only output messages which are higher than the output level you set. The default is to display only INFO messages or higher, so it won't show DEBUG and VERBOSE messages. If you want to see debug messages, then you set:

Output.level(Output.DISP_DEBUG)

The Output methods are:

Output.VERBOSE
Output.DEBUG
Output.INFO
Output.WARNING
Output.ERROR 

You select the messages to be displayed in your functions by doing Output.'DESIRED_LEVEL'('message',input_1,input2) as in the sprintf or fprintf matlab format. I.e, Output.INFO('The variable value is %d',variable). For the WARNING and ERROR messages you may specify also the identifier, as 'PACKAGE:METHOD:ERROR_ID', and by doing so, the output will be on matlab's warning and error functions. I.e Output.WARNING('MY_PACKAGE:MY_METHOD:MY_ID','Something wrong happened here!').

The output levels available are:

Output.level(Output.DISP_VERBOSE) % Show all messages
Output.level(Output.DISP_DEBUG) % Show debug info warning errors
Output.level(Output.DISP_INFO) % Show info warning errors
Output.level(Output.DISP_WARNING) % Show warning errors
Output.level(Output.DISP_MUTE) % Show only errors.

You can also specify output to a log file by using

Output.place('file_path')

And replace log file (you can also use it to reset current log):

Output.place('file_path',true)

Or reset it to screen

Output.place(1)

Here is a sample of the output using output level DISP_VERBOSE:

>> nilmContainer = NilmFileContainer.newRun('inputFolder','sim_real/','runName','RealHouse','samplesPerFile',60*60*60);
VERBOSE: getFilesOnFolder               Found 2 files on folder 'data/sim_real/'. They are the following:
VERBOSE: getFilesOnFolder                   [1]:data/sim_real/240AM000.csv
VERBOSE: getFilesOnFolder                   [2]:data/sim_real/240AM001.csv
DEBUG:   NilmFileContainer.setRunName   Updating run name to RealHouse_Run5.
INFO:    newRun                         Reading file data/sim_real/240AM000.csv.
VERBOSE: csv_data                       Reading samples (Ignored:0,Read:216000,Remaining:2422014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_1-19:12:46-30_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:216000,Read:216000,Remaining:2206014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_2-20:12:45-30_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:432000,Read:216000,Remaining:1990014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_3-21:12:45-30_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:648000,Read:216000,Remaining:1774014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_4-22:12:45-30_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:864000,Read:216000,Remaining:1558014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_5-23:12:45-30_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:1080000,Read:216000,Remaining:1342014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_6-00:12:44-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:1296000,Read:216000,Remaining:1126014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_7-01:12:43-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:1512000,Read:216000,Remaining:910014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_8-02:12:43-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:1728000,Read:216000,Remaining:694014) at file: sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_9-03:12:43-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:1944000,Read:216000,Remaining:478014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_10-04:12:42-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:2160000,Read:216000,Remaining:262014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_11-05:12:41-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:2376000,Read:216000,Remaining:46014) at file: data/sim_real/240AM000.csv.
DEBUG:   addFiles                       Writing file 'data/NILM_DATA/RealHouse_Run5/RealHouse_Run5-File_12-06:12:41-31_10_2012.mat'
VERBOSE: csv_data                       Reading samples (Ignored:2592000,Read:46014,Remaining:0) at file: data/sim_real/240AM000.csv.
VERBOSE: csv_data                       Reading samples (Ignored:0,Read:169986,Remaining:2799058) at file: data/sim_real/240AM001.csv.
INFO:    readFile                       Found discontinuity while changing from file 'data/sim_real/240AM000.csv' to 'data/sim_real/240AM001.csv'.

As I said, it is not at the final version, but you can help me improve it! x)

Romantic

Answer 2

This is what I ended up doing.

I wrote a function (I called it vprintf, but there are better names.)

I'm not sure that I want to do global variables, but that's a thought.

function vprintf(v,l,varargin)
% VPRINTF(verbosity, verbosity_level_of_statement,sprintf_style_arguments
% 
% 
% example: 
% 
% verbosity = 1;
% vprintf(verbosity,1,'This will print if verbosity is at least 1\n Verbosity = %i\n',verbosity);

if nargin<3
    error('not enough arguments');
end
if v>=l % if verbosity level is >= level of this statment
%     keyboard;
    fprintf(varargin{:});
end

Goddamned

Answer 3

Define a function to replace fprintf, that contains the if statement and the actual printing. And declare verbosity as a global variable, to avoid passing it as an argument every time.

Textile

Answer 4

As an improvement on answers from Frederick and Luis Mendo you can define your vprintf function as a nested function at the end of your function. It will have access to the argument verbosity and you won't need a global variable. Your code would look like this:

function foo = some_complicated_fun(x,y,z,verbosity)

[x,y,z,verbosity] = parse_args(x,y,z,verbosity); % parse args, check nargin, etc

for i=1:5, 

    % whatever    
    % do some work with x,y,z
    % blah blah

    vprintf(1,'Now on iteration %i\n',i); % basic print

    % or, with mutiple levels:
    vprintf(1,'Now on iteration %i\n',i); % basic print
    vprintf(2,'x = %f,y = %f,z=%f %i\n',x,y,z); % more information

    % do more work
end

    % time to define vprintf
    function vprintf(l,varargin)
    % VPRINTF(verbosity, verbosity_level_of_statement,sprintf_style_arguments
    % 
    % 
    % example: 
    % 
    % verbosity = 1;
    % vprintf(1,'This will print if verbosity is at least 1\n Verbosity = %i\n',verbosity);

    if nargin<2
        error('not enough arguments');
    end
    if verbosity>=l % if verbosity level is >= level of this statment
    %     keyboard;
        fprintf(varargin{:});
    end
end

EDIT To overcome the maintainability issue Gunther Struyf mentioned in comments, you can keep the verbosity value in a persistent variable in the vprintf and set it in the first call.

function vprintf(vl,varargin)
% VPRINTF(verbosity);
% VPRINTF(verbosity_level_of_statement,sprintf_style_arguments);

persistent verbosity
if nargin==1
    verbosity = vl;
elseif isempty(verbosity)
    error('verbosity level not set');
end

if verbosity>=vl % if verbosity level is >= level of this statment
%     keyboard;
    fprintf(varargin{:});
end

Then in foo function set it in the beginning and use it in later statements. Maybe a good practice to clear the value in the exit by vprintf([]);

function foo = some_complicated_fun(x,y,z,verbosity)

[x,y,z,verbosity] = parse_args(x,y,z,verbosity); % parse args, check nargin, etc

vprintf(verbosity);
for i=1:5, 

    % whatever    
    % do some work with x,y,z
    % blah blah

    vprintf(1,'Now on iteration %i\n',i); % basic print

    % or, with mutiple levels:
    vprintf(1,'Now on iteration %i\n',i); % basic print
    vprintf(2,'x = %f,y = %f,z=%f %i\n',x,y,z); % more information

    % do more work
end
vprintf([]);

Chatelaine

but then you'd have to copy it to every function you use/uses that functionality which would be a pain, especially if you decide to change something in that nested function – Rothman

@GuntherStruyf That's true. Depends how prevalent this constructs is in the whole code base. I added another solution using persistent variables instead of global variables. – Chatelaine

Answer 5

If I'd wanted to do this, I'd create a Logger class, similar to this with functions like logDebug, logInfo, logWarning and logError. (I actually have done this for lua here).

You'd have to set the loglevel on creation, and the complete functionality and functions can be accessed under the scope of the Logger object (so no global scope pollution and easy implementation in multiple m-files).

So final use of this class would look like this:

%% my fancy script
% init
logger = Logger(Logger.LOGDEBUG)
logger.logDebug('script initialized');

% plot some stuff
logger.logDebug('commencing plot');
plot(rand(4));
logger.logInfo('fancy script ended');

Rothman