More RpcPerformance benchmarks; record non-yaffs disks in procstatlog.

Change-Id: I09a67b8e08aeed02ea03f5d9f590af6a583802d2

7 files changed, 263 insertions, 58 deletions

diff --git a/RpcPerformance/AndroidManifest.xml b/RpcPerformance/AndroidManifest.xml
index 0378a5a..5a81912 100644
--- a/RpcPerformance/AndroidManifest.xml
+++ b/RpcPerformance/AndroidManifest.xml
@@ -4,6 +4,8 @@
       android:versionCode="1"
       android:versionName="1.0">
 
+  <uses-permission android:name="android.permission.WRITE_EXTERNAL_STORAGE" />
+  <uses-permission android:name="android.permission.WRITE_SDCARD" />
   <uses-permission android:name="android.permission.WRITE_SETTINGS" />
 
   <uses-sdk android:minSdkVersion="4" android:targetSdkVersion="7" />
diff --git a/RpcPerformance/res/layout/main.xml b/RpcPerformance/res/layout/main.xml
index 90e33d8..e4f8530 100644
--- a/RpcPerformance/res/layout/main.xml
+++ b/RpcPerformance/res/layout/main.xml
@@ -25,6 +25,20 @@
   </TableRow>
 
   <TableRow>
+    <TextView
+        android:layout_width="wrap_content"
+        android:layout_height="wrap_content"
+        android:text="Profile filename:"
+        />
+
+    <EditText android:id="@+id/trace_edit"
+        android:layout_width="fill_parent"
+        android:layout_height="wrap_content"
+        android:singleLine="true"
+        />
+  </TableRow>
+
+  <TableRow>
     <LinearLayout android:layout_height="wrap_content"
                   android:layout_width="wrap_content"
                   android:orientation="vertical">
@@ -256,6 +270,38 @@
          android:text="cp.Call() no exist" />
     </LinearLayout>
   </TableRow>
+
+  <TableRow>
+    <LinearLayout android:layout_height="wrap_content"
+                  android:layout_width="wrap_content"
+                  android:orientation="vertical">
+      <TextView  
+         android:id="@+id/obtain_text"
+         android:layout_width="fill_parent" 
+         android:layout_height="wrap_content" 
+         android:text="Obtain parcel:" />
+      <Button
+         android:id="@+id/obtain_button"
+         android:layout_width="fill_parent" 
+         android:layout_height="wrap_content" 
+         android:text="Parcel.obtain()" />
+    </LinearLayout>
+
+    <LinearLayout android:layout_height="wrap_content"
+                  android:layout_width="wrap_content"
+                  android:orientation="vertical">
+      <TextView  
+         android:id="@+id/recycle_text"
+         android:layout_width="fill_parent" 
+         android:layout_height="wrap_content" 
+         android:text="Recycle parcel:" />
+      <Button
+         android:id="@+id/recycle_button"
+         android:layout_width="fill_parent" 
+         android:layout_height="wrap_content" 
+         android:text="Parcel.recycle()" />
+    </LinearLayout>
+  </TableRow>
 </TableLayout>
 
 </ScrollView>
diff --git a/RpcPerformance/src/com/android/rpc_performance/IService.aidl b/RpcPerformance/src/com/android/rpc_performance/IService.aidl
index f3f979c..9b50fd5 100644
--- a/RpcPerformance/src/com/android/rpc_performance/IService.aidl
+++ b/RpcPerformance/src/com/android/rpc_performance/IService.aidl
@@ -19,4 +19,7 @@ package com.android.rpc_performance;
 interface IService {
     String pingString(String v);
     void pingVoid();
+
+    void startTracing(String name);
+    void stopTracing();
 }
diff --git a/RpcPerformance/src/com/android/rpc_performance/MiscService.java b/RpcPerformance/src/com/android/rpc_performance/MiscService.java
index 3438ed8..003bd73 100644
--- a/RpcPerformance/src/com/android/rpc_performance/MiscService.java
+++ b/RpcPerformance/src/com/android/rpc_performance/MiscService.java
@@ -19,6 +19,7 @@ package com.android.rpc_performance;
 import android.app.Service;
 import android.content.Intent;
 import android.os.Binder;
+import android.os.Debug;
 import android.os.IBinder;
 import android.util.Log;
 import android.net.LocalServerSocket;
@@ -93,10 +94,16 @@ public class MiscService extends Service {
     }
 
     private final IService.Stub mBinder = new IService.Stub() {
-            public String pingString(String v) {
-                return "some string";
-            }
-            public void pingVoid() {
-            }
-        };
+        public String pingString(String v) {
+            return v;
+        }
+        public void pingVoid() {
+        }
+        public void startTracing(String name) {
+            Debug.startMethodTracing(name);
+        }
+        public void stopTracing() {
+            Debug.stopMethodTracing();
+        }
+    };
 }
diff --git a/RpcPerformance/src/com/android/rpc_performance/ProviderPerfActivity.java b/RpcPerformance/src/com/android/rpc_performance/ProviderPerfActivity.java
index a47c6b7..dbb479c 100644
--- a/RpcPerformance/src/com/android/rpc_performance/ProviderPerfActivity.java
+++ b/RpcPerformance/src/com/android/rpc_performance/ProviderPerfActivity.java
@@ -39,8 +39,10 @@ import android.net.LocalSocket;
 import android.net.LocalSocketAddress;
 import android.net.Uri;
 import android.os.Bundle;
+import android.os.Debug;
 import android.os.Handler;
 import android.os.IBinder;
+import android.os.Parcel;
 import android.os.RemoteException;
 import android.os.SystemClock;
 import android.telephony.TelephonyManager;
@@ -88,6 +90,7 @@ public class ProviderPerfActivity extends Activity {
 
     private ContentResolver cr;
     private int mIterations = 100;
+    private String mTraceName = null;
 
     /** Called when the activity is first created. */
     @Override
@@ -154,13 +157,13 @@ public class ProviderPerfActivity extends Activity {
 
         setButtonAction(R.id.service_button, new Runnable() {
                 public void run() {
-                    final float avgTime = serviceLoop(0);
+                    final float avgTime = serviceLoop(null);
                     endAsyncOp(R.id.service_button, R.id.service_text, avgTime);
                 }});
 
         setButtonAction(R.id.service2_button, new Runnable() {
                 public void run() {
-                    final float avgTime = serviceLoop(1);
+                    final float avgTime = serviceLoop("xyzzy");
                     endAsyncOp(R.id.service2_button, R.id.service2_text, avgTime);
                 }});
 
@@ -181,6 +184,18 @@ public class ProviderPerfActivity extends Activity {
                     final float avgTime = callLoop("XXXXXXXX");  // non-existent
                     endAsyncOp(R.id.call2_button, R.id.call2_text, avgTime);
                 }});
+
+        setButtonAction(R.id.obtain_button, new Runnable() {
+                public void run() {
+                    final float avgTime = parcelLoop(true);
+                    endAsyncOp(R.id.obtain_button, R.id.obtain_text, avgTime);
+                }});
+
+        setButtonAction(R.id.recycle_button, new Runnable() {
+                public void run() {
+                    final float avgTime = parcelLoop(false);
+                    endAsyncOp(R.id.recycle_button, R.id.recycle_text, avgTime);
+                }});
     }
 
     @Override public void onResume() {
@@ -199,35 +214,39 @@ public class ProviderPerfActivity extends Activity {
 
     private void setButtonAction(int button_id, final Runnable r) {
         final Button button = (Button) findViewById(button_id);
-        if (button == null) {
-            Log.w(TAG, "Bogus button ID: " + button_id);
-            return;
-        }
         button.setOnClickListener(new View.OnClickListener() {
-                public void onClick(View v) {
-                    TextView tv = (TextView) findViewById(R.id.iterations_edit);
-                    if (tv != null) {
-                        try {
-                            mIterations = Integer.parseInt(tv.getText().toString());
-                        } catch (NumberFormatException e) {
-                            Log.w(TAG, "Invalid iteration count", e);
-                            if (tv != null) tv.setText(Integer.toString(mIterations));
-                        }
-                    }
-
-                    button.setEnabled(false);
-                    new Thread(r).start();
+            public void onClick(View v) {
+                button.requestFocus();
+                button.setEnabled(false);
+
+                TextView tvIter = (TextView) findViewById(R.id.iterations_edit);
+                try {
+                    mIterations = Integer.parseInt(tvIter.getText().toString());
+                } catch (NumberFormatException e) {
+                    Log.w(TAG, "Invalid iteration count", e);
+                    if (tvIter != null) tvIter.setText(Integer.toString(mIterations));
+                }
+
+                TextView tvTrace = (TextView) findViewById(R.id.trace_edit);
+                String name = tvTrace.getText().toString();
+                if (name != null && name.length() > 0) {
+                    mTraceName = name;
+                    Debug.startMethodTracing(name);
                 }
-            });
+
+                new Thread(r).start();
+            }
+        });
     }
 
     private void endAsyncOp(final int button_id, final int text_id, final float avgTime) {
         mHandler.post(new Runnable() {
-                public void run() {
-                    Button button = (Button) findViewById(button_id);
-                    button.setEnabled(true);
-                    setTextTime(text_id, avgTime);
-                }});
+            public void run() {
+                Debug.stopMethodTracing();
+                findViewById(button_id).setEnabled(true);
+                setTextTime(text_id, avgTime);
+            }
+        });
     }
 
     private void setTextTime(int id, float avgTime) {
@@ -397,33 +416,33 @@ public class ProviderPerfActivity extends Activity {
     }
 
     // Returns average cross-process dummy query time in milliseconds.
-    private float serviceLoop(int amtEncoding) {
+    private float serviceLoop(String value) {
         if (mServiceStub == null) {
             Log.v(TAG, "No service stub.");
             return -999;
         }
+
         String dummy = null;
         try {
+            if (mTraceName != null) mServiceStub.startTracing(mTraceName + ".service");
+
             long sumNanos = 0;
-            int count = 0;
             for (int i = 0; i < mIterations; i++) {
                 long lastTime = System.nanoTime();
-                if (amtEncoding == 0) {
+                if (value == null) {
                     mServiceStub.pingVoid();
                 } else {
-                    dummy = mServiceStub.pingString(dummy);
+                    value = mServiceStub.pingString(value);
                 }
-                long curTime = System.nanoTime();
-                long duration = curTime - lastTime;
-                count++;
-                sumNanos += duration;
+                sumNanos += System.nanoTime() - lastTime;
             }
-            float averageMillis = (float) sumNanos / (float) (count != 0 ? count : 1) / 1000000.0f;
-            Log.v(TAG, "service loop: total: " + count + "; avg_ms=" + averageMillis);
-            return averageMillis;
+
+            if (mTraceName != null) mServiceStub.stopTracing();
+
+            return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f;
         } catch (RemoteException e) {
-            Log.e(TAG, "error in service loop: " + e);
-            return -999.0f;
+            Log.e(TAG, "Binder call failed", e);
+            return -999;
         }
     }
 
@@ -467,6 +486,27 @@ public class ProviderPerfActivity extends Activity {
         }
     }
 
+    // Returns average operation time in milliseconds.
+    // obtain: true = measure obtain(), false = measure recycle()
+    private float parcelLoop(boolean obtain) {
+        long sumNanos = 0;
+        for (int i = 0; i < mIterations; i++) {
+            if (obtain) {
+                long lastTime = System.nanoTime();
+                Parcel p = Parcel.obtain();
+                sumNanos += System.nanoTime() - lastTime;
+                p.recycle();
+            } else {
+                Parcel p = Parcel.obtain();
+                long lastTime = System.nanoTime();
+                p.recycle();
+                sumNanos += System.nanoTime() - lastTime;
+            }
+        }
+
+        return (float) sumNanos / Math.max(1.0f, (float) mIterations) / 1000000.0f;
+    }
+
     // Returns average milliseconds.
     private static final int MODE_READ = 0;
     private static final int MODE_WRITE = 1;
diff --git a/procstatlog/procstatlog.c b/procstatlog/procstatlog.c
index 443efce..c4c39e3 100644
--- a/procstatlog/procstatlog.c
+++ b/procstatlog/procstatlog.c
@@ -44,10 +44,15 @@
 //
 // Files read:
 //
-// /proc/*/stat  - for all running processes
-// /proc/*/wchan - for all running processes
-// /proc/stat    - one per line, e.g. "/proc/stat:intr"
-// /proc/yaffs   - one per line, e.g. "/proc/yaffs:userdata:nBlockErasures"
+// /proc/*/stat       - for all running/selected processes
+// /proc/*/wchan      - for all running/selected processes
+// /proc/binder/stats - per line: "/proc/binder/stats:BC_REPLY"
+// /proc/diskstats    - per device: "/proc/diskstats:mmcblk0"
+// /proc/net/dev      - per interface: "/proc/net/dev:rmnet0"
+// /proc/stat         - per line: "/proc/stat:intr"
+// /proc/yaffs        - per device/line: "/proc/yaffs:userdata:nBlockErasures"
+// /sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state
+//                    - per line: "/sys/.../time_in_state:245000"
 
 struct data {
     char *name;            // filename, plus ":var" for many-valued files
@@ -89,11 +94,14 @@ static void read_data(struct data *data, const char *filename) {
 }
 
 // Read a name/value file and write data entries for each line.
-// The delimiter is used to split each line into name and value.
-// If terminator is non-NULL, processing stops after it appears.
 // Returns the number of entries written (always <= stats_count).
+//
+// delimiter: used to split each line into name and value
+// terminator: if non-NULL, processing stops after this string
+// skip_words: skip this many words at the start of each line
 static int read_lines(
-        const char *filename, char delimiter, const char *terminator,
+        const char *filename,
+        char delimiter, const char *terminator, int skip_words,
         struct data *stats, int stats_count) {
     char buf[8192];
     int fd = open(filename, O_RDONLY);
@@ -121,7 +129,13 @@ static int read_lines(
          line = strtok(NULL, "\n")) {
         // Line format: <sp>name<delim><sp>value
 
+        int i;
         while (isspace(*line)) ++line;
+        for (i = 0; i < skip_words; ++i) {
+            while (isgraph(*line)) ++line;
+            while (isspace(*line)) ++line;
+        }
+
         char *name_end = strchr(line, delimiter);
         if (name_end == NULL) continue;
 
@@ -280,12 +294,13 @@ static struct data *read_stats(char *names[], int name_count) {
 
     struct data *end = stats + stats_count;
     next += read_proc_yaffs(next, stats + stats_count - next);
-    next += read_lines("/proc/net/dev", ':', NULL, next, end - next);
-    next += read_lines("/proc/stat", ' ', NULL, next, end - next);
-    next += read_lines("/proc/binder/stats", ':', "\nproc ", next, end - next);
+    next += read_lines("/proc/net/dev", ':', NULL, 0, next, end - next);
+    next += read_lines("/proc/stat", ' ', NULL, 0, next, end - next);
+    next += read_lines("/proc/binder/stats", ':', "\nproc ", 0, next, end - next);
+    next += read_lines("/proc/diskstats", ' ', NULL, 2, next, end - next);
     next += read_lines(
             "/sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state",
-            ' ', NULL, next, end - next);
+            ' ', NULL, 0, next, end - next);
 
     assert(next < stats + stats_count);
     next->name = NULL;
diff --git a/procstatlog/procstatreport.py b/procstatlog/procstatreport.py
index a5af829..d38feac 100755
--- a/procstatlog/procstatreport.py
+++ b/procstatlog/procstatreport.py
@@ -112,10 +112,19 @@ pages: <nobr>%(nPageReads)d read</nobr>,
 blocks: <nobr>%(nBlockErasures)d erased</nobr>
 """
 
+DISK_LABEL = """
+<span style="font-size: 150%%">disk: %(device)s</span><br>
+sectors: <nobr>%(reads)d read</nobr>, <nobr>%(writes)d written</nobr>
+"""
+
+DISK_TIME_LABEL = """
+msec: <nobr>%(msec)d waiting</nobr>
+"""
+
 NET_LABEL = """
 <span style="font-size: 150%%">net: %(interface)s</span><br>
 bytes: <nobr>%(tx)d tx</nobr>,
-<nobr>%(rx)d rx</nobr><br>
+<nobr>%(rx)d rx</nobr>
 """
 
 PAGE_END = """
@@ -478,11 +487,94 @@ def WriteOutput(history, log_filename, filename):
         })
 
     #
+    # Output non-YAFFS statistics
+    #
+
+    disk_reads = {}
+    disk_writes = {}
+    disk_msec = {}
+    total_io = max_io = max_msec = 0
+
+    last_state = {}
+    for when, state in sorted_history:
+        for key in state:
+            if not key.startswith("/proc/diskstats:"): continue
+
+            last = last_state.get(key, "").split()
+            next = state.get(key, "").split()
+            if not (last and next): continue
+
+            reads = int(next[2]) - int(last[2])
+            writes = int(next[6]) - int(last[6])
+            msec = int(next[10]) - int(last[10])
+            total_io += reads + writes
+            max_io = max(max_io, reads, writes)
+            max_msec = max(max_msec, msec)
+
+            diskstats, device = key.split(":", 1)
+            disk_reads.setdefault(device, {})[when] = reads
+            disk_writes.setdefault(device, {})[when] = writes
+            disk_msec.setdefault(device, {})[when] = msec
+
+        last_state = state
+
+    io_cutoff = total_io / 100
+    for num, device in enumerate(sorted(disk_reads.keys())):
+        if [d for d in disk_reads.keys()
+            if d.startswith(device) and d != device]: continue
+
+        reads, writes = disk_reads[device], disk_writes[device]
+        total_reads, total_writes = sum(reads.values()), sum(writes.values())
+        if total_reads + total_writes <= io_cutoff: continue
+
+        WriteChartData(
+            ["reads", "writes"], [reads, writes],
+            os.path.join(files_dir, "disk%d.csv" % num))
+
+        out.append(CHART % {
+            "id": cgi.escape("disk%d" % num),
+            "id_js": json.write("disk%d" % num),
+            "label_html": DISK_LABEL % {
+                "device": cgi.escape(device),
+                "reads": total_reads,
+                "writes": total_writes,
+            },
+            "filename_js": json.write("%s/disk%d.csv" % (files_url, num)),
+            "options_js": json.write({
+                "colors": ["gray", "teal"],
+                "dateWindow": date_window,
+                "fillGraph": True,
+                "height": 75,
+                "valueRange": [0, max_io * 11 / 10],
+            }),
+        })
+
+        msec = disk_msec[device]
+
+        WriteChartData(
+            ["msec"], [msec],
+            os.path.join(files_dir, "disk%d_time.csv" % num))
+
+        out.append(CHART % {
+            "id": cgi.escape("disk%d_time" % num),
+            "id_js": json.write("disk%d_time" % num),
+            "label_html": DISK_TIME_LABEL % {"msec": sum(msec.values())},
+            "filename_js": json.write("%s/disk%d_time.csv" % (files_url, num)),
+            "options_js": json.write({
+                "colors": ["blue"],
+                "dateWindow": date_window,
+                "fillGraph": True,
+                "height": 50,
+                "valueRange": [0, max_msec * 11 / 10],
+            }),
+        })
+
+    #
     # Output per-process CPU and page faults collected earlier
     #
 
-    cpu_cutoff = (total_sys + total_user) / 1000
-    faults_cutoff = sum(total_faults.values()) / 200
+    cpu_cutoff = (total_sys + total_user) / 200
+    faults_cutoff = sum(total_faults.values()) / 100
     for start, pid in sorted([(s, p) for p, s in process_start.iteritems()]):
         sys = sum([n for n, d in process_sys.get(pid, {}).values()])
         sys_user = sum([n for n, d in process_sys_user.get(pid, {}).values()])