AU: reduce logging when generating delta update

delta_diff_generator.cc

 // Copyright (c) 2010 The Chromium OS 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 "update_engine/delta_diff_generator.h"
 
 #include <errno.h>
 #include <fcntl.h>
 #include <inttypes.h>
 #include <sys/stat.h>
@@ skipping 93 matching lines @@
 // fields of blocks by calling this function.
 // For each block in 'operation' that is read or written, find that block
 // in 'blocks' and set the reader/writer field to the vertex passed.
 // 'graph' is not strictly necessary, but useful for printing out
 // error messages.
 bool AddInstallOpToBlocksVector(
     const DeltaArchiveManifest_InstallOperation& operation,
     vector<Block>* blocks,
     const Graph& graph,
     Vertex::Index vertex) {
-  LOG(INFO) << "AddInstallOpToBlocksVector(" << vertex << "), "
-            << graph[vertex].file_name;
   // See if this is already present.
   TEST_AND_RETURN_FALSE(operation.dst_extents_size() > 0);
 
   enum BlockField { READER = 0, WRITER, BLOCK_FIELD_COUNT };
   for (int field = READER; field < BLOCK_FIELD_COUNT; field++) {
     const int extents_size =
         (field == READER) ? operation.src_extents_size() :
         operation.dst_extents_size();
     const char* past_participle = (field == READER) ? "read" : "written";
     const google::protobuf::RepeatedPtrField<Extent>& extents =
         (field == READER) ? operation.src_extents() : operation.dst_extents();
     Vertex::Index Block::*access_type =
         (field == READER) ? &Block::reader : &Block::writer;
 
     for (int i = 0; i < extents_size; i++) {
       const Extent& extent = extents.Get(i);
       if (extent.start_block() == kSparseHole) {
         // Hole in sparse file. skip
         continue;
       }
       for (uint64_t block = extent.start_block();
            block < (extent.start_block() + extent.num_blocks()); block++) {
-        LOG(INFO) << "ext: " << i << " block: " << block;
         if ((*blocks)[block].*access_type != Vertex::kInvalidIndex) {
           LOG(FATAL) << "Block " << block << " is already "
                      << past_participle << " by "
                      << (*blocks)[block].*access_type << "("
                      << graph[(*blocks)[block].*access_type].file_name
                      << ") and also " << vertex << "("
                      << graph[vertex].file_name << ")";
         }
         (*blocks)[block].*access_type = vertex;
       }
@@ skipping 167 matching lines @@
   vector<Block>::size_type blocks_copied_count = 0;
 
   // For each extent in extents, write the data into BZ2_bzWrite which
   // sends it to an output file.
   // We use the temporary buffer 'buf' to hold the data, which may be
   // smaller than the extent, so in that case we have to loop to get
   // the extent's data (that's the inner while loop).
   for (vector<Extent>::const_iterator it = extents.begin();
        it != extents.end(); ++it) {
     vector<Block>::size_type blocks_read = 0;
+    float printed_progress = -1;
     while (blocks_read < it->num_blocks()) {
       const int copy_block_cnt =
           min(buf.size() / kBlockSize,
               static_cast<vector<char>::size_type>(
                   it->num_blocks() - blocks_read));
       ssize_t rc = pread(image_fd,
                          &buf[0],
                          copy_block_cnt * kBlockSize,
                          (it->start_block() + blocks_read) * kBlockSize);
       TEST_AND_RETURN_FALSE_ERRNO(rc >= 0);
       TEST_AND_RETURN_FALSE(static_cast<size_t>(rc) ==
                             copy_block_cnt * kBlockSize);
       BZ2_bzWrite(&err, bz_file, &buf[0], copy_block_cnt * kBlockSize);
       TEST_AND_RETURN_FALSE(err == BZ_OK);
       blocks_read += copy_block_cnt;
       blocks_copied_count += copy_block_cnt;
-      LOG(INFO) << "progress: " << ((float)blocks_copied_count)/block_count;
+      float current_progress =
+          static_cast<float>(blocks_copied_count) / block_count;
+      if (printed_progress + 0.1 < current_progress ||
+          blocks_copied_count == block_count) {
+        LOG(INFO) << "progress: " << current_progress;
+        printed_progress = current_progress;
+      }
     }
   }
   BZ2_bzWriteClose(&err, bz_file, 0, NULL, NULL);
   TEST_AND_RETURN_FALSE(err == BZ_OK);
   bz_file = NULL;
   TEST_AND_RETURN_FALSE_ERRNO(0 == fclose(file));
   file = NULL;
 
   vector<char> compressed_data;
   LOG(INFO) << "Reading compressed data off disk";
@@ skipping 387 matching lines @@
   cuts.reserve(edges.size());
 
   uint64_t scratch_blocks_used = 0;
   for (set<Edge>::const_iterator it = edges.begin();
        it != edges.end(); ++it) {
     cuts.resize(cuts.size() + 1);
     vector<Extent> old_extents =
         (*graph)[it->first].out_edges[it->second].extents;
     // Choose some scratch space
     scratch_blocks_used += graph_utils::EdgeWeight(*graph, *it);
-    LOG(INFO) << "using " << graph_utils::EdgeWeight(*graph, *it)
-              << " scratch blocks ("
-              << scratch_blocks_used << ")";
     cuts.back().tmp_extents =
         scratch_allocator.Allocate(graph_utils::EdgeWeight(*graph, *it));
     // create vertex to copy original->scratch
     cuts.back().new_vertex = graph->size();
     graph->resize(graph->size() + 1);
     cuts.back().old_src = it->first;
     cuts.back().old_dst = it->second;
 
     EdgeProperties& cut_edge_properties =
         (*graph)[it->first].out_edges.find(it->second)->second;
@@ skipping 223 matching lines @@
   for (vector<CutEdgeVertexes>::const_iterator it = cuts.begin(),
            e = cuts.end(); it != e; ++it) {
     uint64_t cut_blocks_needed = 0;
     for (vector<Extent>::const_iterator jt = it->tmp_extents.begin(),
              je = it->tmp_extents.end(); jt != je; ++jt) {
       cut_blocks_needed += jt->num_blocks();
     }
     blocks_needed += cut_blocks_needed;
     cuts_blocks_needed[&*it] = cut_blocks_needed;
   }
-  LOG(INFO) << "Need to find " << blocks_needed << " blocks for "
-            << cuts.size() << " cuts";
-  
+
   // Find enough blocks
   ExtentRanges scratch_ranges;
   // Each block that's supplying temp blocks and the corresponding blocks:
   typedef vector<pair<Vertex::Index, ExtentRanges> > SupplierVector;
   SupplierVector block_suppliers;
   uint64_t scratch_blocks_found = 0;
-  LOG(INFO) << "scan from " << (*reverse_op_indexes)[old_dst] + 1
-            << " to " << op_indexes->size();
   for (vector<Vertex::Index>::size_type i = (*reverse_op_indexes)[old_dst] + 1,
            e = op_indexes->size(); i < e; ++i) {
     Vertex::Index test_node = (*op_indexes)[i];
     if (!(*graph)[test_node].valid)
       continue;
     // See if this node has sufficient blocks
     ExtentRanges ranges;
     ranges.AddRepeatedExtents((*graph)[test_node].op.dst_extents());
     ranges.SubtractExtent(ExtentForRange(
         kTempBlockStart, kSparseHole - kTempBlockStart));
@@ skipping 12 matching lines @@
     if (ranges.blocks() + scratch_blocks_found > blocks_needed) {
       // trim down ranges
       vector<Extent> new_ranges = ranges.GetExtentsForBlockCount(
         blocks_needed - scratch_blocks_found);
       ranges = ExtentRanges();
       ranges.AddExtents(new_ranges);
     }
     scratch_ranges.AddRanges(ranges);
     block_suppliers.push_back(make_pair(test_node, ranges));
     scratch_blocks_found += ranges.blocks();
-    LOG(INFO) << "Adding " << ranges.blocks() << " blocks. Now have "
-              << scratch_ranges.blocks();
     if (scratch_ranges.blocks() >= blocks_needed)
       break;
   }
   if (scratch_ranges.blocks() < blocks_needed) {
     LOG(INFO) << "Unable to find sufficient scratch";
     TEST_AND_RETURN_FALSE(ConvertCutsToFull(graph,
                                             new_root,
                                             data_fd,
                                             data_file_size,
                                             op_indexes,
@@ skipping 26 matching lines @@
                                          real_extents);
 
     // Fix the new node w/ the real blocks. Since the new node is just a
     // copy operation, we can replace all the dest extents w/ the real
     // blocks.
     DeltaArchiveManifest_InstallOperation *op =
         &(*graph)[it->new_vertex].op;
     op->clear_dst_extents();
     DeltaDiffGenerator::StoreExtents(real_extents, op->mutable_dst_extents());
   }
-  LOG(INFO) << "Done subbing in for cut set";
   return true;
 }
 
 }  // namespace {}
 
 // Returns true if |op| is a no-op operation that doesn't do any useful work
 // (e.g., a move operation that copies blocks onto themselves).
 bool DeltaDiffGenerator::IsNoopOperation(
     const DeltaArchiveManifest_InstallOperation& op) {
   return (op.type() == DeltaArchiveManifest_InstallOperation_Type_MOVE &&
@@ skipping 532 matching lines @@
 
   LOG(INFO) << "All done. Successfully created delta file.";
   return true;
 }
 
 const char* const kBsdiffPath = "bsdiff";
 const char* const kBspatchPath = "bspatch";
 const char* const kDeltaMagic = "CrAU";
 
 };  // namespace chromeos_update_engine