logging in android

Android provides a set of powerful log utilities to make our developing life easier. If you've ever used the OutputDebugString function and the DebugView on windows, you'll find they works very similar to android's counterpart in the sense of user experience. We can start the application normally, then start DDMS at anytime we want to view the application's log message.
How to use the logging system
The android logging system defines a set of APIs to be used in our code. These functions have similar signature but different verbosity level.Only error, warning and info logs are always kept. Verbose and debug are intended for using in development stage only.
To use them, we just need to add a function call to Log API in the place in our code that we have interests with desired message. The first argument tag identifies the caller. It's a good practice to define a constant string for this tag. Use hard coded string within the function call directly makes our code harder to maintain.

Performance concern
The android logging system is so powerful and user friendly that we can easily make excessive use of it in our code. But does it bring any performance penalty to our application? Let's try out this with an experiment. The idea is pretty simple, we'll make a loop of 10,000 iteration and perform logging in each iteration. And we'll record the time before and after the loop in a log file (/data/data/package_name/files/log_perf.log).
The code snippet below does this. It exercises the logging loop each time we click on a button.

package com.rmd;

import java.io.FileNotFoundException;
import java.io.FileOutputStream;
import java.io.PrintStream;
import java.text.SimpleDateFormat;
import java.util.Date;

import android.app.Activity;
import android.content.Context;
import android.os.Bundle;
import android.util.Log;
import android.view.View;
import android.widget.Button;

public class main extends Activity {
 /** Called when the activity is first created. */
 @Override
 public void onCreate(Bundle savedInstanceState) {
  super.onCreate(savedInstanceState);
  setContentView(R.layout.main);

  Button btn = (Button) this.findViewById(R.id.btnGenerateLog);
  btn.setOnClickListener(new View.OnClickListener() {

   @Override
   public void onClick(View v) {
    System.gc();
    try {
     FileOutputStream fos = v.getContext().openFileOutput("log_perf.log",
       Context.MODE_APPEND);
     PrintStream ps = new PrintStream(fos);
     Date dt = new Date();
     SimpleDateFormat sdf = new SimpleDateFormat("yyyy/MM/dd hh:mm:ss");
     ps.printf("start on\t" + sdf.format(dt) + "\n");
     for (int i = 0; i < 10000; ++i) {
      Log.v("log_perf_test", "hello raymond");
     }
     dt = new Date();
     ps.printf("end on\t\t" + sdf.format(dt) + "\n");
     ps.close();
    } catch (FileNotFoundException ex) {
     Log.e("log_perf_test", "can't open file\n" + ex.getMessage());
    }
   }
  });
 }
} 

After we downloaded the apk file to the emulator, we'll run the application five times in different circumstances, with and without DDMS running to see if there is any difference.

-- DDMS turned off --
start on    2009/11/09 09:33:11
end on      2009/11/09 09:33:12
start on    2009/11/09 09:33:17
end on      2009/11/09 09:33:18
start on    2009/11/09 09:33:20
end on      2009/11/09 09:33:21
start on  2009/11/09 09:33:30
end on      2009/11/09 09:33:31
start on    2009/11/09 09:33:33
end on      2009/11/09 09:33:34

-- DDMS truned on --
start on    2009/11/09 09:33:59
end on      2009/11/09 09:34:02
start on    2009/11/09 09:34:05
end on      2009/11/09 09:34:08
start on    2009/11/09 09:34:11
end on      2009/11/09 09:34:14
start on    2009/11/09 09:34:17
end on      2009/11/09 09:34:20
start on    2009/11/09 09:35:06
end on        2009/11/09 09:35:10

-- /sbin/adbd killed --
start on    2009/11/09 09:35:53
end on      2009/11/09 09:35:54
start on    2009/11/09 09:35:57
end on      2009/11/09 09:35:59
start on    2009/11/09 09:36:01
end on      2009/11/09 09:36:02
start on    2009/11/09 09:36:05
end on      2009/11/09 09:36:06
start on    2009/11/09 09:36:08
end on      2009/11/09 09:36:09

From the log file above, we can see that the loop takes about 1 second to finish without DDMS running or having adbd process killed. And the loop takes about 3 seconds to finish if DDMS is running and capturing log message. On average, Log.v function runs at the level of tenth of millisecond. So, I tend to believe we don't need to bother much about performance penalty. It's more important to have correct logic and easier debugging facility.