Add granular file tracing.

base/files/file_posix.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/files/file.h"
 
 #include <errno.h>
 #include <fcntl.h>
 #include <sys/stat.h>
 #include <unistd.h>
 
 #include "base/files/file_path.h"
 #include "base/logging.h"
 #include "base/metrics/sparse_histogram.h"
 #include "base/posix/eintr_wrapper.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/threading/thread_restrictions.h"
+#include "base/trace_event/trace_event.h"
 
 #if defined(OS_ANDROID)
 #include "base/os_compat_android.h"
 #endif
 
 namespace base {
 
 // Make sure our Whence mappings match the system headers.
 COMPILE_ASSERT(File::FROM_BEGIN   == SEEK_SET &&
                File::FROM_CURRENT == SEEK_CUR &&
@@ skipping 139 matching lines @@
 
 PlatformFile File::TakePlatformFile() {
   return file_.release();
 }
 
 void File::Close() {
   if (!IsValid())
     return;
 
   ThreadRestrictions::AssertIOAllowed();
+  TRACE_EVENT1(kTraceGroup, "Close", "path", path_.AsUTF8Unsafe());
   file_.reset();
 }
 
 int64 File::Seek(Whence whence, int64 offset) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
+  TRACE_EVENT1(kTraceGroup, "Seek", "path", path_.AsUTF8Unsafe())
 
 #if defined(OS_ANDROID)
   COMPILE_ASSERT(sizeof(int64) == sizeof(off64_t), off64_t_64_bit);
   return lseek64(file_.get(), static_cast<off64_t>(offset),
                  static_cast<int>(whence));
 #else
   COMPILE_ASSERT(sizeof(int64) == sizeof(off_t), off_t_64_bit);
   return lseek(file_.get(), static_cast<off_t>(offset),
                static_cast<int>(whence));
 #endif
 }
 
 int File::Read(int64 offset, char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
   if (size < 0)
     return -1;
 
+  TRACE_EVENT2(kTraceGroup, "Read", "path", path_.AsUTF8Unsafe(), "size", size);

[groby-ooo-7-16, 2015/04/28 20:26:55]

Given that you call this every read/seek/etc, might be worth storing the UTF8
path name.

[Dan Beam, 2015/04/29 02:48:03]

this is only called while tracing (in which case all of chrome is equally
slower)

+
   int bytes_read = 0;
   int rv;
   do {
     rv = HANDLE_EINTR(pread(file_.get(), data + bytes_read,
                             size - bytes_read, offset + bytes_read));
     if (rv <= 0)
       break;
 
     bytes_read += rv;
   } while (bytes_read < size);
 
   return bytes_read ? bytes_read : rv;
 }
 
 int File::ReadAtCurrentPos(char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
   if (size < 0)
     return -1;
 
+  TRACE_EVENT2(kTraceGroup, "ReadAtCurrentPost", "path", path_.AsUTF8Unsafe(),
+               "size", size);
+
   int bytes_read = 0;
   int rv;
   do {
     rv = HANDLE_EINTR(read(file_.get(), data + bytes_read, size - bytes_read));
     if (rv <= 0)
       break;
 
     bytes_read += rv;
   } while (bytes_read < size);
 
   return bytes_read ? bytes_read : rv;
 }
 
 int File::ReadNoBestEffort(int64 offset, char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
-
+  TRACE_EVENT2(kTraceGroup, "ReadNoBestEffort", "path", path_.AsUTF8Unsafe(),
+               "size", size);
   return HANDLE_EINTR(pread(file_.get(), data, size, offset));
 }
 
 int File::ReadAtCurrentPosNoBestEffort(char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
   if (size < 0)
     return -1;
 
+  TRACE_EVENT2(kTraceGroup, "ReadAtCurrentPosNoBestEffort",
+               "path", path_.AsUTF8Unsafe(), "size", size);
   return HANDLE_EINTR(read(file_.get(), data, size));
 }
 
 int File::Write(int64 offset, const char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
 
   if (IsOpenAppend(file_.get()))
     return WriteAtCurrentPos(data, size);
 
   DCHECK(IsValid());
   if (size < 0)
     return -1;
 
+  TRACE_EVENT2(kTraceGroup, "Write", "path", path_.AsUTF8Unsafe(),
+               "size", size);
+
   int bytes_written = 0;
   int rv;
   do {
     rv = HANDLE_EINTR(pwrite(file_.get(), data + bytes_written,
                              size - bytes_written, offset + bytes_written));
     if (rv <= 0)
       break;
 
     bytes_written += rv;
   } while (bytes_written < size);
 
   return bytes_written ? bytes_written : rv;
 }
 
 int File::WriteAtCurrentPos(const char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
   if (size < 0)
     return -1;
 
+  TRACE_EVENT2(kTraceGroup, "WriteAtCurrentPos", "path", path_.AsUTF8Unsafe(),
+               "size", size);
+
   int bytes_written = 0;
   int rv;
   do {
     rv = HANDLE_EINTR(write(file_.get(), data + bytes_written,
                             size - bytes_written));
     if (rv <= 0)
       break;
 
     bytes_written += rv;
   } while (bytes_written < size);
 
   return bytes_written ? bytes_written : rv;
 }
 
 int File::WriteAtCurrentPosNoBestEffort(const char* data, int size) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
   if (size < 0)
     return -1;
 
+  TRACE_EVENT2(kTraceGroup, "WriteAtCurrentPosNoBestEffort",
+               "path", path_.AsUTF8Unsafe(), "size", size);
   return HANDLE_EINTR(write(file_.get(), data, size));
 }
 
 int64 File::GetLength() {
   DCHECK(IsValid());
 
+  TRACE_EVENT1(kTraceGroup, "GetLength", "path", path_.AsUTF8Unsafe())
+
   stat_wrapper_t file_info;
   if (CallFstat(file_.get(), &file_info))
     return false;
 
   return file_info.st_size;
 }
 
 bool File::SetLength(int64 length) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
+
+  TRACE_EVENT2(kTraceGroup, "SetLength", "path", path_.AsUTF8Unsafe(),
+               "length", length);
+
   return !CallFtruncate(file_.get(), length);
 }
 
 bool File::SetTimes(Time last_access_time, Time last_modified_time) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
 
+  TRACE_EVENT1(kTraceGroup, "SetTimes", "path", path_.AsUTF8Unsafe())
+
   timeval times[2];
   times[0] = last_access_time.ToTimeVal();
   times[1] = last_modified_time.ToTimeVal();
 
   return !CallFutimes(file_.get(), times);
 }
 
 bool File::GetInfo(Info* info) {
   DCHECK(IsValid());
 
+  TRACE_EVENT1(kTraceGroup, "GetInfo", "path", path_.AsUTF8Unsafe())
+
   stat_wrapper_t file_info;
   if (CallFstat(file_.get(), &file_info))
     return false;
 
   info->FromStat(file_info);
   return true;
 }
 
 File::Error File::Lock() {
+  TRACE_EVENT1(kTraceGroup, "Lock", "path", path_.AsUTF8Unsafe())
   return CallFctnlFlock(file_.get(), true);
 }
 
 File::Error File::Unlock() {
+  TRACE_EVENT1(kTraceGroup, "Unlock", "path", path_.AsUTF8Unsafe())
   return CallFctnlFlock(file_.get(), false);
 }
 
 File File::Duplicate() {
   if (!IsValid())
     return File();
 
+  TRACE_EVENT1(kTraceGroup, "Duplicate", "path", path_.AsUTF8Unsafe())
+
   PlatformFile other_fd = dup(GetPlatformFile());
   if (other_fd == -1)
     return File(OSErrorToFileError(errno));
 
   File other(other_fd);
   if (async())
     other.async_ = true;
   return other.Pass();
 }
 
@@ skipping 72 matching lines @@
   CHECK_EQ(file_memory_checksum_, computed_checksum) << "corrupted fd memory";
 }
 
 void File::MemoryCheckingScopedFD::UpdateChecksum() {
   ComputeMemoryChecksum(&file_memory_checksum_);
 }
 
 // NaCl doesn't implement system calls to open files directly.
 #if !defined(OS_NACL)
 // TODO(erikkay): does it make sense to support FLAG_EXCLUSIVE_* here?
-void File::DoInitialize(const FilePath& name, uint32 flags) {
+void File::DoInitialize(uint32 flags) {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(!IsValid());
 
+  TRACE_EVENT1(kTraceGroup, "Initialize", "path", path_.AsUTF8Unsafe())
+
   int open_flags = 0;
   if (flags & FLAG_CREATE)
     open_flags = O_CREAT | O_EXCL;
 
   created_ = false;
 
   if (flags & FLAG_CREATE_ALWAYS) {
     DCHECK(!open_flags);
     DCHECK(flags & FLAG_WRITE);
     open_flags = O_CREAT | O_TRUNC;
@@ skipping 31 matching lines @@
   else if (flags & FLAG_APPEND)
     open_flags |= O_APPEND | O_WRONLY;
 
   COMPILE_ASSERT(O_RDONLY == 0, O_RDONLY_must_equal_zero);
 
   int mode = S_IRUSR | S_IWUSR;
 #if defined(OS_CHROMEOS)
   mode |= S_IRGRP | S_IROTH;
 #endif
 
-  int descriptor = HANDLE_EINTR(open(name.value().c_str(), open_flags, mode));
+  int descriptor = HANDLE_EINTR(open(path_.value().c_str(), open_flags, mode));
 
   if (flags & FLAG_OPEN_ALWAYS) {
     if (descriptor < 0) {
       open_flags |= O_CREAT;
       if (flags & FLAG_EXCLUSIVE_READ || flags & FLAG_EXCLUSIVE_WRITE)
         open_flags |= O_EXCL;   // together with O_CREAT implies O_NOFOLLOW
 
-      descriptor = HANDLE_EINTR(open(name.value().c_str(), open_flags, mode));
+      descriptor = HANDLE_EINTR(open(path_.value().c_str(), open_flags, mode));
       if (descriptor >= 0)
         created_ = true;
     }
   }
 
   if (descriptor < 0) {
     error_details_ = File::OSErrorToFileError(errno);
     return;
   }
 
   if (flags & (FLAG_CREATE_ALWAYS | FLAG_CREATE))
     created_ = true;
 
   if (flags & FLAG_DELETE_ON_CLOSE)
-    unlink(name.value().c_str());
+    unlink(path_.value().c_str());
 
   async_ = ((flags & FLAG_ASYNC) == FLAG_ASYNC);
   error_details_ = FILE_OK;
   file_.reset(descriptor);
 }
 #endif  // !defined(OS_NACL)
 
 bool File::DoFlush() {
   ThreadRestrictions::AssertIOAllowed();
   DCHECK(IsValid());
+
 #if defined(OS_NACL)
   NOTIMPLEMENTED();  // NaCl doesn't implement fsync.
   return true;
-#elif defined(OS_LINUX) || defined(OS_ANDROID)
+#else
+  TRACE_EVENT1(kTraceGroup, "Flush", "path", path_.AsUTF8Unsafe())
+#if defined(OS_LINUX) || defined(OS_ANDROID)
   return !HANDLE_EINTR(fdatasync(file_.get()));
 #else
   return !HANDLE_EINTR(fsync(file_.get()));
-#endif
+#endif  // defined(OS_LINUX) || defined(OS_ANDROID)
+#endif  // defined(OS_NACL)
 }
 
 void File::SetPlatformFile(PlatformFile file) {
   DCHECK(!file_.is_valid());
   file_.reset(file);
 }
 
 }  // namespace base