03 January 2011

Excising android.util.Log calls when you publish your Android app

The Android platform includes support for debuggers, but since real programmers don't use debuggers (and because I'm not using Eclipse), I use the equivalent of printf: android.util.Log to follow what's going on in my programs

Because there's no macro processor in Java (or Scala, which I'm actually using), there are two standard ways to remove debugging statements from your code before you ship it:

  1. Prefix every call to the logging function with an if statement:
    if (GlobalConstants.DEBUG) Log.v(GlobalConstants.LOG_TAG, "isBetterLocation(): isSignificantlyNewer->ret true")
    A Makefile (or whatever your build system) can set GlobalConstants.DEBUG appropriately. This is regrettably verbose.* It also doesn't actually eliminate the code: maybe the Scala compiler isn't optimizing hard enough, but when I disassemble the class files (actually, the dex files), they're still there, wasting precious bytes, even though they never will be called.**

  2. Tell Proguard to eliminate the calls to logging functions with a configuration directive like:
    -assumenosideeffects class android.util.Log {public static int v(...);public static int d(...);public static int w(...);public static int i(...);}

    Since I'm running Proguard anyway (the Scala Build Tool Android plugin runs it by default), this would seem to be the best way.

The only problem was that Method #2 didn't work. I tried loads of variants on the class specification for -assumenosideeffects, but the Log statements kept showing up in the code.

It turned out that there were no less than two reasons why it wasn't working.

The first was that the scala-build-tool Android plugin had switched off Proguard's optimization by adding the -dontoptimize switch in AndroidProject.scala:

def proguardTask = task {
val args = "-injars" :: mainCompilePath.absolutePath+File.pathSeparator+
(if (!proguardInJars.getPaths.isEmpty) File.pathSeparator+proguardInJars.getPaths.map(_+"(!META-INF/MANIFEST.MF)").mkString(File.pathSeparator) else "") ::
"-outjars" :: classesMinJarPath.absolutePath ::
"-libraryjars" :: libraryJarPath.getPaths.mkString(File.pathSeparator) ::
"-dontwarn" :: "-dontoptimize" :: "-dontobfuscate" :: // <------ ROFL "-keep public class * extends android.app.Activity" :: "-keep public class * extends android.app.Service" :: [definition continues ...]

Fortunately, that was easy to fix once I knew what to look for. I copied proguardTask into the MainProject class of my project/build/MyProjectName.scala project definition file, slapped on an override, and deleted the offending "-dontoptimize" (and "-dontobfuscate", too).

Despite that fix, Proguard still wouldn't erase the Log calls. Casting around for the second reason (and wondering why I didn't just solve this problem with a few calls to sed in a Makefile), I unzipped the generated .apk and disassembled the classes.dex file with dedexer. Inside was code like this:

sget-object v1,com/mycode/android/GlobalConstants$.MODULE$ Lcom/mycode/android/GlobalConstants$;
invoke-interface {v1},com/mycode/android/GlobalDebugState/DEBUG ; DEBUG()Z
move-result v1
if-eqz v1,l1d01c
sget-object v1,com/mycode/android/GlobalConstants$.MODULE$ Lcom/mycode/android/GlobalConstants$;
invoke-virtual {v1},com/mycode/android/GlobalConstants$/LOG_TAG ; LOG_TAG()Ljava/lang/String;
move-result-object v1
const-string v2,"clickTakePicture: erasing picture..."
invoke-static {v1,v2},android/util/Log/v ; v(Ljava/lang/String;Ljava/lang/String;)I
move-result v1
invoke-static {v1},java/lang/Integer/valueOf ; valueOf(I)Ljava/lang/Integer;
(code continues...)
Note that after the call to Log.v, the program is doing something with the result of that function: it's calling valueOf on the result. Why on earth is it doing this?

My guess was that it had something to do with the fact that the if statement in Scala is also an expression: it evaluates to the value of the last expression in the code block it executed. So you can write the following:

scala> 3 + (if (1>2) 5 else 6)
res0: Int = 9

I hypothesized that the Scala compiler was keeping the result of the Log.v function call around so that if (GlobalConstants.DEBUG) would be able to return a value. Now, it shouldn't have done so, because I wasn't actually using the if expression. Call this a bug in Scala. Proguard, noticing that the program was doing something with the return value of Log, refused to optimize it away.

On that hunch, I tried removing all of the if (GlobalConstants.DEBUG) conditionals. The Log statements disappeared. Success!

Well, not quite. Because every code block in Scala evaluates to the value of the last expression evaluated inside that block, there were code blocks where the call to Log was the last such call. For instance, this case, where I was using pattern matching as flow control but ignoring the return value of the match:

mevt.getAction match {
case x:Int if x == MotionEvent.ACTION_DOWN || x == MotionEvent.ACTION_MOVE => {
mLastTB = topBottomNeither
mLastY = mevt.getY
Log.v(SQConstants.LOG_TAG, "onTouchEvent started new state:" + mLastTB + " mevtY:" + mLastY)
case _ => null

To get the Scala compiler to discard the return value from that Log.v, I inserted a null after it, as the last expression in the case x... block above. Success!

Well, not exactly. Now my code is peppered with unnecessary nulls (or any literal). I should track down the offending bug in Scala, but I think I've sunk enough time into this one already.) And, to make matters worse, -assumenosideeffects eliminates the function calls but won't optimize away any expressions in the arguments to the log functions: e.g., if you have the line:

Log.v(Constants.LOG_TAG, " NPT.before() called on ctx:" + context);

You get this (completely unused) computation in the output:

.line 623
new-instance v0,scala/collection/mutable/StringBuilder
invoke-direct {v0},scala/collection/mutable/StringBuilder/ ; ()V
const-string v1," NPT.before() called on ctx:"
invoke-virtual {v0,v1},scala/collection/mutable/StringBuilder/append ; append(Ljava/lang/Object;)Lscala/collection/mutable/StringBuilder;
move-result-object v0
invoke-virtual {v0,v8},scala/collection/mutable/StringBuilder/append ; append(Ljava/lang/Object;)Lscala/collection/mutable/StringBuilder;
move-result-object v0
invoke-virtual {v0},scala/collection/mutable/StringBuilder/toString ; toString()Ljava/lang/String;

[note that you have to turn off obfuscation to see the actual method and object names]

We could tell Proguard to assumenosideeffects for scala.collection.mutable.StringBuilder, but then it might optimize away .append calls that we do want. What would be ideal would be if we could tell Proguard that calls on the StringBuilder object had no side effects except on that object itself, so that it could notice that the object was never used and delete it. This is really the sort of thing a compiler should do, though---all the more reason why it would be ideal if a construct like

if(GlobalObject.DEBUG) whatever()

...would be dropped by the compiler if GlobalObject.DEBUG were declared both false and final.

Conclusion: short of hacking a macro processor (read:sed, because I'm lazy) into the build process, there's no easy way to conditionally and completely excise those debugging statements. I'm going to leave them. Users won't see them, but they will take up (a negligable amount of) space and waste (a negligable number of) cycles.

* Famed hacker Jamie Zawniski had this complaint decade ago. A StackOverflow poster notes that, to this day, #ifdefDEBUG is still hard to simulate in Java.

** Computer storage may be infinite, but mobile phones are small and wireless connections are slow.

No comments:

Post a Comment

About Me

blog at barillari dot org Older posts at http://barillari.org/blog