01-19-11 - Good practices

Some things that I always regret when I don't do them. These are as much reminders for myself not to get lazy as they are finger-wags at you all.

1. Save every log.

My programs generally log very verbosely. I log more to the file than to stdout. The key thing is that you shouldn't just overwrite your previous log. You should save every log of your runs *forever*. Disks are big, there is no reason to ever clean this up.

Your log file should contain the time & date of the run + the time & date of the build (this is mildly annoying to do in practice, just using __DATE__ somewhere in your code doesn't work because that module may not be fresh compiled). Ideally it would have the P4 sync state of the code as well (see comments). Ideally it would also log the modtime and/or checksum of every file that you take as input, so you can associate a run with the condition of the files it loads as well.

This is an okay way to start your logs :

// log the command line :
void lprintfCommandLine(int argc,char * argv[])
    for(int i=0;i < argc;i++)
        lprintf("%s ",argv[i]);

// log the command line + build time :
void lprintfLogHeader(const char * progName,int argc,char * argv[])
    __time64_t long_time;
    _time64( &long_time );
    // note: asctime has a \n in it already
    lprintf("Log opened : %s",asctime(_localtime64( &long_time )));
    lprintf("%s built %s, %s\n",progName,__DATE__,__TIME__);    
    lprintf("args: ");

Something I've doing for a while now is to automatically write my logs to "c:\logs\programname.log" , and if a previous one of those exists I append it onto programname.prev . That's okay but not perfect, for one thing the big prev file gets hard to search through; perhaps worse, it doesn't play well with running multiple instances of your program at once (their logs get interleaved and the prev is moved at a random spot).

My videotest does something that I like even better. It makes a new log file for each run and names it by the date/time of the run and the command line args. They all go in a dir "c:\logs\programname\" and then the names are like "-c0rpjt1.rmv-irparkjoy_444_720p_lagarith_50.avi-p-d0-Sun-Jan-16-15-42-27-2011.log" which makes it very easy for me to find particular runs and see what the args were.

2. Make tests reproducable.

Often I'll run some tests and record the result, and then later when I go back to it I'm confused by what was run exactly, where the data files were, etc. Doing this is really just about discipline. There are a few things that I believe help :

2.A. Always make batch files. When you run command lines, do not just type in the command line and run it to execute your test. Put the command line in a batch file and run that. Then check your batch file into perforce!

2.B. Take the results of the test and write a quick note about how they were run and what they were testing. eg. exactly what #define did you flip in the code to run the test. It's so easy to not take this step because you think "its obvious" what you did, but 12 months later it won't be obvious. Check this into perforce.

2.C. For more interesting tests, make a directory and copy the whole thing! Copy in the data files that you ran on, the batch files, the results, and the code! Also copy in any tools you used! eg. if you used imagemagick or ffmpeg or whatever as part of your process, just copy it in to the directory. Disk is cheap and huge! Save the whole thing somewhere so you have a record of what exactly you ran.

2.D. If you changed code to run the test - check it in! Even if it's just for the test run - check in the test code and then check it in back to normal. eg. if you flip a #define or change some constants - check that in to P4 with a description saying "for test such and such".

(ASIDE : the first company I ever worked out was CTC in Houston. At CTC when we finished a major project, we would make an archive of the entire project and everything we needed to reproduce it. That means the code, the compilers, any tools or libraries, and the whole OS. We could take an archive and restore it to a fresh machine and instantly have a working system that would build it. I just thought that made a lot of sense and obviously every developer did that, right? Nope. I have yet to see anyone else do it since. People seem to believe that they can just archive the code without recording everything that needed to be done to the tools and build environment and so on to make a working build system.)

3. Never leave magic numbers in code.

I often stumble back on some old code and find something like :

x = y + 7 * z;

umm.. WTF where did that 7 come from? Even if you only use that value in one spot in the code, give it a name. eg.

const double c_averageACtoDCratio = 7;

x = y + c_averageACtoDCratio * z;

Ah, okay. Which is related to :

4. When values come from training or tweaking, document exactly how they were generated.

Ideally you saved the training run as per #2, so you should be able to just add a comment like

// this value comes from training; see train_averageACtoDCratio.bat

You may think you've found the perfect tweak value, but some day you may come back to it and think "where did this come from? am I sure this right? does this still apply since I've changed a bunch of other things since then?". Also, what data did you train it on exactly? Does that data actually reflect what you're using it for now?

Ideally ever value that comes from training can be regenerated at any time. Don't just do your training run and save the value and then break your training code. Assume that any tweak value will have to be regenerated in the future.

5. Some notes on default values.

In more complex programs, don't just put the default value of a parameter in its initializer, eg.

int maxNumMovecSearches = 32;

no no. The problem is that the initializer can be hidden away in a weird spot, and there may be multiple initializers, and you may want to reset values to their defaults, etc. Instead give it a proper name, like :

const int c_maxNumMovecSearches_default = 32;

int maxNumMovecSearches = c_maxNumMovecSearches_default;

Now you can also show defaults on the command line, such as :

lprintf("videotest usage:\n");
lprintf("-m# : max num movec searches [%d]\n",c_maxNumMovecSearches_default);

For args that are unclear what scale they're on, you should also show a reasonable parameter range, eg.

lprintf("-l# : lagrange lambda [%f] (0.1 - 1.0)\n",c_lagrangeLambda_default);

(though this example violates my own rule of baking constants into strings)

6. Make all options into proper enums with names.

You should never have a "case 2:" in your code or an "if ( mode == 1 )". Every time I short-cut and do that I wind up regretting it. For example I had some code doing :


To select the 6th qtable. Of course that inevitably leads to bugs when I decide to reorder the qtables.

Give your enums the right name automatically using XX macros , eg. :

#define DCTQTableIndex_XX  \
    XX(eDctQ_Flat) YY(=0),\

enum EDCTQTableIndex
    #define XX(x) x
    #define YY(y) y
    #undef XX
    #undef YY

const char * c_DCTQTableIndex_names[] =
    #define XX(x) #x
    #define YY(y)
    #undef XX
    #undef YY

And then make sure you echo the name when somebody selects an enum numerically so you can show that they are correct.

Do not keep a table of names and a table of enums that must be kept in sync manually. In general do not keep *anything* in code that must be kept in sync manually.

Show them as part of the command line help, eg :

        for(int f=0;f < eImDiff_Count;f++)
            myprintf("%2d : %s\n",f,c_imDiffTypeNames[f]);

For example if you tried to be a good boy and had something like :

    lprintf("dct qtable names:\n");
    lprintf("0: flat\n");
    lprintf("1: jpeg\n");

You have just "hard-coded" the values through the use of string constants. Don't bake in values.

One nice way is if command line arg "-m#" selects mode #, then "-m" with no arg should list the modes ("-m" followed by anything non-numeric should do the same).

If somebody has to go read the docs to use your program, then your command line user interface (CLUI) has failed. Furthermore docs are another example of bad non-self-maintaining redundancy. The list of arg mappings in the docs can get out of sync with the code : never rely on the human programmer to keep things in sync, make the code be correct automagically.

7. Copy the exe.

It's so easy during work to think of the exe as a temp/derivative item which you are replacing all the time, but you will often get yourself into scenarios where it's hard to get back to some old state and you want to play with the exe from that old state. So just copy off the exe every so often. Any time you generate major test results is a good time for this - output your CSV test files or whatever and just take a copy of the exe used to make the tests.

A semi-related practice that I've taken up now is to copy off the exe out of the build target location any time I run a test, so that I can still build new versions, and if I do build new versions, the version I wanted to test isn't fouled. eg. I use something like :

run_vt_test.bat :

  call zc -o release\vt.exe r:\vt_test.exe
  r:\vt_test.exe %*

8. Automate your processing

If you're running some process that requires a few steps - like run this exe, take the number it outputs, copy it into this code, recompile, run that on this data file - automate it.

It might seem like it's faster just to do it yourself than it is to automate it. That may in fact be true, but automating it has lots of ancillary value that makes it worth doing.

For one thing, it documents the process. Rather than just having to write a document that describes "how to export a character for the game" (which you will inevitably not write or not keep up to date), instead you have your batch file or script or whatever that does the steps.

For another, it gives you a record of what's being done and a way to exactly repeat the process if there are bugs. Any time you have a human step in the process it adds an element of non-repeatability and uncertainty, is this character broken because there's a bug or just because someone didn't follow the right steps?

There are some very simple ghetto tricks to easy automation. One is to have your program fwrite some text to a batch file and then just run that batch.

More generally, I wish my computer kept a full journal of everything I ever did on it. Everything I type, the state of every file, everything run should be stored in a history which I can play back like a movie any time I want. I should just be able to go, "mmkay, restore to the condition of May 13, 2009 and play back from 3:15 to 3:30". Yeah, maybe that's a bit unrealistic, but it certainly is possible in certain limitted cases (eg. apps that don't access the net or take input from any weird drivers) which are the cases I mainly care about.


castano said...

> Ideally it would have the P4 sync state of the code as well

I did that for a while on the witness, but checking the svn status is sometimes quite slow and that triggered some complains when the game took too long to start. :(

cbloom said...

Were you doing it at run time or build time?

The thing I haven't figured out how to do is to bake the build time & p4 sync number into the program in an elegant way.

You can easily have a BuildTime.cpp file that you echo that info into. The tricky thing is knowing when to generate that. I could easily generate it every time I hit F7, but that would cause linkage to happen even if no other code files changed.

What I want is to be able to hit F7 and have it be a nop if no compiling is needed. But if any compiling is needed, then run my script step to generate BuildTime.cpp and compile that before linkage.

Sam said...

Wouldn't RCS keywords do what you want with regard to the revision number? You just have to change all your files where you want keyword expansion to type text+k.

Tom Forsyth said...

> #define DCTQTableIndex_XX

Ah, perfect. I've always had a nagging feeling there was a trick like this to generate both enums and names, and never got around to figuring out the details. Thanks!

castano said...

At runtime. The thing that I was most concerned with was reproducing bug reports. Ie, when the game crashes on an artist's PC, but not on mine it's usually due to bad local data. This has not happened recently, so I felt it was not worth the load delay, and hopefully we have other messages to diagnose these problems.

I still dump some subversion info and that at least tells us what's the last revision he was sync'd to. We check in our builds, so that gives us the exact binary he was using.

It may actually be worth dumping the extra info in our crash handler, hmm...

cbloom said...

"Wouldn't RCS keywords do what you want with regard to the revision number?"

Eh, while that stuff is cool, I don't think it helps here at all unless there's some mojo I don't know.

What I want is for the EXE to contain a string which describes the exact p4 state to sync to in order to rebuild that same EXE. (If your client is sunc up to some changelist #, this would just be the changelist #, more generally it's a changelist # + a list of deviations from that; see for example http://stackoverflow.com/questions/47007/determining-the-last-changelist-synced-to-in-perforce).

Sam said...

Ah right, yeah I'm not sure of any magic to do that. Hmm, although on the Perforce kb site here they list a keyword $Change$ but don't explain what it is, and after a quick google I couldn't find it explained in any RCS/CVS websites..

Sam said...

Hm it might be possible to do a custom RCS keyword using that method to find the synced changelist in combination with a trigger script as mentioned here.

cbloom said...

Yeah, the real problem though is that there's no way to trigger a script at the right time in VC.

There's no build event for "if you need to compile anything, let me generate another .c and please compile that too".

Actually the same kind of build event would be useful for my old AutoPrefs idea and other automatic-codegen type ideas.

Anonymous said...

>>> 3. Never leave magic numbers in code.

The worse I've seen is people putting in streaming code a magic constant related to hardware DMA address alignment and size limits, where there were actually #defined constants already available for that! Fuckers...

RCL said...

What I want is for the EXE to contain a string which describes the exact p4 state to sync to in order to rebuild that same EXE. (If your client is sunc up to some changelist #, this would just be the changelist #, more generally it's a changelist # + a list of deviations from that)

Do you mean local changes by those deviations?

It can be done by inserting the custom build step which would dump:

1) p4 CL you last synced to (#have)
2) list of open files (p4 open)
3) diff of every open file (p4 diff )

Dumping such a 'build footprint' should result in a new .cpp file which would contain the above as string literal.

Also, perhaps the footprinting tool should compare the result for identity with existing file and not to overwrite it if not necessary, that would avoid "linking on every F7" problem.

RCL said...

Addendum: I think you may fake a "let me generate a .cpp file if you pressed F7" event by adding a custom-built project (e.g. by make tool) to your solution and making your project depend on that. Haven't tried that though.

cbloom said...

Hi RCL, as I've tried to explain before, getting a dump of the p4 build footprint is not the hard part. It's doing it *if and only if* the build is not fresh that I can't figure out. Otherwise your dump to a cpp file will cause a re-link that's unnecessary.

old rants