Thursday, September 12, 2013

Exception like stack trace in pure C

All of us have seen stack traces printed out after an exception has been thrown.

Java:
Exception in thread "main" java.lang.NullPointerException
        at com.example.myproject.Book.getTitle(Book.java:16)
        at com.example.myproject.Author.getBookTitles(Author.java:25)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

Python:
Traceback (most recent call last):
  File "test.py", line 8, in b
    c()
  File "test.py", line 13, in c
    assert False
AssertionError

You may find a plenty of information about other languages online.

Stack traces are almost always helpful when debugging. But what if exceptions just don't exist in the language or are forbidden? Well, I don't sympathize C++ exceptions and I don't appreciate exceptions over error codes in other languages, but this is out of the scope of the blog post.

So, let's be more specific. We are in the pure C world. We can't use exceptions. Now what? Do something ugly like:

  1. printf("OMG, something happened\n");
  2. return;

What if we need to finish executing the program if that something happens?

  1. char* ar = malloc(23423423);
  2. if(ar == NULL)
  3. {
  4.  printf("oh, ar can't be allocated\n");
  5.  exit(errorcode);
  6. }

What if there are a number of functions where ar can be allocated (not the same ar, but just local to function ar)? What if we reuse ar in such a way that it is assigned to a different variable and that malloced again, or realloced? What if we want to easily weed errors out of a normal output? Oh, we could use

  1. fprintf(stderr, "my error");

But what if we now want to change output from stderr to another stream? Or what if we want a uniform format for all of our errors? Or what if we just want to track our error from the origin all the way up to the place where it was called from? Imagine an XML or Json parser which blows up somewhere in a node parsing? What will that error from inside the depths of the parser tell you? Nothing at all, it is generic. It would be much lovelier to see who called that parser and with what arguments. This is where stack trace would be handy. And here is what we are aiming for in C:

Error: example.c:35 (my_function) - [0000001b] custom error
 ----> someFile.c:50 (super_hero_function) - [0000001b]
 ----> main.c:163 (main) - [00000001]

This is an example of a proper stack trace. It has an origin in example.c::my_function() and it traces all the way back to main.c::main() through someFile.c::super_hero_function(), but it also outputs a return result of each of those functions on its way.

This is a code which serves this kind of output:

  1. //
  2. // developed by Sergey Markelov (09-2013)
  3. //
  4. #ifndef GENERIC_LOGGER
  5. #define GENERIC_LOGGER
  6. #include <stdio.h>
  7. extern FILE *errStream;
  8. extern FILE *outStream;
  9. #define ERR_STREAM              errStream
  10. #define OUT_STREAM              outStream
  11. #define ERROR_PREFIX            "Error: "
  12. #define STANDARD_PREFIX         ""
  13. #define ERROR_CONTINUE_PREFIX   " ----> "
  14. #define STRINGIFY(x) #x
  15. #define TOSTRING(x)  STRINGIFY(x)
  16. #define _LOG(stream, prefix, format, ...) \
  17.     { fprintf(stream, "%s (%s) - " format "\n", prefix __FILE__ ":" TOSTRING(__LINE__), __func__, ##__VA_ARGS__); }
  18. #define LogError(format, ...) \
  19.     { _LOG(ERR_STREAM, ERROR_PREFIX, format, ##__VA_ARGS__); }
  20. #define Log(format, ...) \
  21.     { _LOG(OUT_STREAM, STANDARD_PREFIX, format, ##__VA_ARGS__); }
  22. //
  23. // @brief this macro originates the error. Functions down the stack should use
  24. //        ContinueErrorEx() or ContinueError() to propagate the error behavior.
  25. //
  26. //        In the log it will look like:
  27. //
  28. //        Error: example.c:35 (my_function) - [0000001b] custom error
  29. //         ----> someFile.c:50 (process) - [0000001b]
  30. //         ----> main.c:163 (main) - [00000001]
  31. //
  32. // @param result the value which needs to be logged
  33. // @param resultSpecifier printf() specifier for the result. Ex. "%d" means @c result is of type @c int
  34. //        you can also use "0x%08x" to make it Hex
  35. // @param format, ... - custom formatted message
  36. //
  37. #define OriginateErrorEx(result, resultSpecifier, format, ...) \
  38.     { LogError("[" resultSpecifier "] " format, result, ##__VA_ARGS__); return result; }
  39. //
  40. // @see OriginateErrorEx
  41. //
  42. #define OriginateError(result, resultSpecifier) \
  43.     { LogError("[" resultSpecifier "] ", result); return result; }
  44. //
  45. // @see OriginateErrorEx
  46. //
  47. #define ContinueErrorEx(result, resultSpecifier, format, ...) \
  48.     { _LOG(ERR_STREAM, ERROR_CONTINUE_PREFIX, \
  49.            "[" resultSpecifier "] " format, result, ##__VA_ARGS__); return result; }
  50. //
  51. // @see OriginateErrorEx
  52. //
  53. #define ContinueError(result, resultSpecifier) \
  54.     { _LOG(ERR_STREAM, ERROR_CONTINUE_PREFIX, \
  55.            "[" resultSpecifier "] ", result); return result; }
  56. #endif

and here is an example usage:

  1. //
  2. // developed by Sergey Markelov (09-2013)
  3. //
  4. #include "logger.h"
  5. //
  6. // defined in logger.h
  7. //
  8. FILE *errStream;
  9. FILE *outStream;
  10. static int blowUp()
  11. {
  12.     if(ftell(NULL) == -1) OriginateErrorEx(-1, "%d", "ftell() caused errno %d - '%s'", errno, strerror(errno));
  13.     return 0;
  14. }
  15. int main(void)
  16. {
  17.     int res;
  18.     errStream = stderr;
  19.     outStream = stdout;
  20.     res = blowUp();
  21.     if(res != 0) ContinueError(res, "%d");
  22.     return 0;
  23. }

ftell will fail on NULL file stream and this stack trace will be outputed to stderr:

Error: main.c:15 (blowUp) - [-1] ftell() caused errno [3450] - 'Descriptor is not valid'
 ----> main.c:27 (main) - [-1]

As you may see we have everything we need to understand what exactly happened and when and who caused that error to happen.

In the code above I used variadic macros. That version is GNU specific and you can't find it in a compiler from MS. Clang supports it out of the box unless you specify to warn about that with -Wgnu. GCC, of course, supports it.

When I say that MS doesn't support variadic macros, that is not to be confused with the full GNU support when you separate format part from the actual variadic part. This way, we can do tricky things like that:

  1. #define _LOG(stream, prefix, format, ...) \
  2.     { fprintf(stream, "%s (%s) - " format "\n", prefix __FILE__ ":" TOSTRING(__LINE__), __func__, ##__VA_ARGS__); }

that is the most generic logging function from the above. It constructs the format string concatenating
"%s (%s) - " with format which is passed as an argument to a macro.

Also I used __LINE__ stringification discussed here.

All that logging mechanism is pure C style macros, thus the original code after preprocessing will be as fast as ordinary fprintf's here and there in your code. So, at the run time we pay no extra cost for a lot of extra functionality!

And all you have to do to use this logging mechanism is to include the h file and to declare errStream and outStream. You can link those to stderr and stdout. Or you can fopen a file and link the stream to there.

Monday, August 19, 2013

Recursive grep and performance comparison with find + grep

This is how you can recursively grep starting from current directory. 

find . -name "pattern" -exec grep "search_pattern" '{}' \;

That's been a known pattern to grep recursively. But let me introduce you to a better approach described in the second answer here which is saying that since grep 2.5.2 shipped on August 2006 we are happy to use a functionality from grep itself. So, check this out

00:47:50:~/Coding$ time greprepo "*.java" "flint" . 
./clojure/repos/my/jalint2/HelloWorld.java: Native.loadLibrary("flint", Flint.class); 
./clojure/repos/my/jalint2/HelloWorld.java: System.setProperty("jna.library.path", "../flint2"); 
./clojure/repos/rebcabin/jalint2/HelloWorld.java: Native.loadLibrary("flint", Flint.class); 
./clojure/repos/rebcabin/jalint2/HelloWorld.java: System.setProperty("jna.library.path", "../flint2");

real 0m0.134s 
user 0m0.120s 
sys 0m0.014s

00:48:25:~/Coding$ time find . -name "*.java" -exec grep flint '{}' \; 
Native.loadLibrary("flint", Flint.class); 
System.setProperty("jna.library.path", "../flint2"); 
Native.loadLibrary("flint", Flint.class); 
System.setProperty("jna.library.path", "../flint2"); 

real 0m0.545s 
user 0m0.289s 
sys 0m0.212s

Isn't it impressive? And greprepo is my alias to

alias greprepo='grep --exclude-dir ".{git,svn}" -R --mmap --include'

Performance boost is also due to mmap which is ok if you don't change files you are currently greping. Don't try to do mmap on network share or if you change the stuff. Anyways, whithout mmap performance is still much more impressive than with find 

01:02:46:~/Coding$ time grep --exclude-dir ".{git,svn}" -R --include "*.java" "flint" .
./clojure/repos/my/jalint2/HelloWorld.java:            Native.loadLibrary("flint", Flint.class);
./clojure/repos/my/jalint2/HelloWorld.java:        System.setProperty("jna.library.path", "../flint2");
./clojure/repos/rebcabin/jalint2/HelloWorld.java:            Native.loadLibrary("flint", Flint.class);
./clojure/repos/rebcabin/jalint2/HelloWorld.java:        System.setProperty("jna.library.path", "../flint2");

real 0m0.146s
user 0m0.130s
sys 0m0.015s

mmap will do its magic on really huge files. ~/Coding is not a storage for huge files as you can presume.

Of course you may notice I used --exclude-dir with grep, but here is one more

1:02:56:~/Coding$ time grep -R --include "*.java" "flint" .
./clojure/repos/my/jalint2/HelloWorld.java:            Native.loadLibrary("flint", Flint.class);
./clojure/repos/my/jalint2/HelloWorld.java:        System.setProperty("jna.library.path", "../flint2");
./clojure/repos/rebcabin/jalint2/HelloWorld.java:            Native.loadLibrary("flint", Flint.class);
./clojure/repos/rebcabin/jalint2/HelloWorld.java:        System.setProperty("jna.library.path", "../flint2");

real 0m0.135s
user 0m0.118s
sys 0m0.017s

which makes me thinking of pre caching :) Anyway, find doesn't feature an easy option to exclude directories. There is some "workaround", which I didn't understand how to easily use. But even then find + grep is much slower, than grep alone.



UPDATE [Sep 17, 2013]



My friend pointed me at that there is a slightly better approach to find + grep to one that I used above, which is to combine find with xargs. So, here are all three approaches listed from the slowest to the fastest:

0 (raspberry) 14:43:20:~/.vim$ time find . -name "*.vim" -exec grep -Hn --color=always tab '{}' \; > /dev/null

real    0m1.855s
user    0m0.370s
sys     0m1.070s

0 (raspberry) 14:43:26:~/.vim$ time find . -name "*.vim" -print0 | xargs -0 grep -Hn --color=always tab > /dev/null

real    0m0.213s
user    0m0.080s
sys     0m0.110s

0 (raspberry) 14:43:31:~/.vim$ time greprepo "*.vim" "tab" . > /dev/null

real    0m0.172s
user    0m0.080s
sys     0m0.080s

Once again, grep alone wins. However, it's worth saying, find + xargs is much faster than find -exec. 

But don't forget that using grep only approach you have exclusions which I talked about in the original post.

Monday, May 13, 2013

VTL - Velocity Template Language syntax highlighter + filetype plugin for Vim

In the beginning of 2012 I created Velocity Template Language plugin for Vim. This post is meant to be no more than to bind everything together and bring it to one place. The plugin itself can be found on vim.org or on github. The description is taken from vim.org page and is posted below unchanged.

An example of vtl file syntax highlighting with the colors I use looks like:



This is a Velocity Template Language syntax highlighter + filetype plugin. It features support of shorthand $my.some.reference(something) and longhand ${my.some.reference(something)} notations for both references and directives (including user defined macros). Everything described on the official web page (http://velocity.apache.org/engine/devel/user-guide.html) is supported. Supports directives along with user defined macros one line and multiline. Error handling of incorrectly placed directives. References can be mutliline, so that

$myref.long.array[ 3 ].
something.
take
.fromHere()

is also supported. Directives and references' methods and arrays can contain comments, unformatted text and doxygen comments.

Special references sequences (e.g. $foreach.parent.index or $foreach.topmost.hasNext) are recognized as keywords if they are contained.

Two types of strings are supported. References inside double quotes "" are highlighted.

Matchit support is introduced which allows you to jump from the start of a block (i.e. #if(), #foreach(), #define(), #macro(), #@any_user_macro()) to the end of the block (#end | #{end}) and vice versa with % just like you jump between opening and closing brackets.

Also all multiline directives supports folding.

Only directives described on the official web-page are recognized as system directives, user defined directives are recognized differently and can be one line or multiline.

Comments are automatically expanded to the next line while a user types them and appropriately recognized by vim engine.

NOTE: this differs from velocity.vim (http://www.vim.org/scripts/script.php?script_id=541) in many cases, which provides only basic capability, which doesn't include recogniton of multiline entities. It doesn't support system directives and error handling. No way to jump between openinig and closing directive. No support of nonparsable blocks. That script is really very basic (no offence to the author).

This one provides all the capabilites described on the official web-page (http://velocity.apache.org/engine/devel/user-guide.html)
install details
unpack to ~/.vim, or install pathogen.vim and unpack to ~/.vim/bundle/vtl

to make the sytax highlighting and ftplugin work appropriately one may need to add
autocmd BufRead,BufNewFile *.vm set syntax=vm filetype=vm
to his/her ~/.vim/ftdetect/syntax.vim