tamer: tameld: Use buffered writes

This was an oversight.  The difference is significant.  I had my suspicions
about this when I noticed the huge difference in time between writing to
/dev/null vs. an actual file during profiling.

On one of our systems, here's the number of syscalls _before_ this change:

  $ strace -c target/release/tameld --emit xmle -o foo foo.xmlo
  % time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
   85.05    4.966192          16    318473           write
    7.23    0.421977          13     32298           lstat
    6.53    0.381424          15     25113           read
    0.75    0.043691          13      3350           readlink
    0.25    0.014713          61       241           close
    0.12    0.007167          30       241           openat
    0.05    0.003175         151        21           munmap
    0.01    0.000488          14        35           brk
    0.01    0.000292           9        33           mmap
    0.00    0.000266          38         7           mremap
    0.00    0.000004           1         3           sigaltstack
    0.00    0.000000           0         6           fstat
    0.00    0.000000           0         1           poll
    0.00    0.000000           0        11           mprotect
    0.00    0.000000           0         7           rt_sigaction
    0.00    0.000000           0         1           rt_sigprocmask
    0.00    0.000000           0         6         6 access
    0.00    0.000000           0         1           execve
    0.00    0.000000           0         1           arch_prctl
    0.00    0.000000           0         1           sched_getaffinity
    0.00    0.000000           0         1           set_tid_address
    0.00    0.000000           0         1           set_robust_list
    0.00    0.000000           0         2           prlimit64
  ------ ----------- ----------- --------- --------- ----------------
  100.00    5.839389                379854         6 total

And _after_:

  $ strace -c target/release/tameld --emit xmle -o foo foo.xmlo
  % time     seconds  usecs/call     calls    errors syscall
  ------ ----------- ----------- --------- --------- ----------------
   45.21    0.435010          13     32298           lstat
   40.09    0.385752          15     25113           read
    6.14    0.059113          21      2809           write
    4.75    0.045687          14      3350           readlink
    2.51    0.024115         100       241           close
    0.84    0.008045          33       241           openat
    0.26    0.002468         118        21           munmap
    0.06    0.000580          17        35           brk
    0.06    0.000566          17        33           mmap
    0.03    0.000279          40         7           mremap
    0.02    0.000181          16        11           mprotect
    0.01    0.000087          15         6         6 access
    0.01    0.000082          12         7           rt_sigaction
    0.01    0.000075          13         6           fstat
    0.00    0.000027           9         3           sigaltstack
    0.00    0.000024          12         2           prlimit64
    0.00    0.000018          18         1           execve
    0.00    0.000016          16         1           poll
    0.00    0.000013          13         1           sched_getaffinity
    0.00    0.000012          12         1           rt_sigprocmask
    0.00    0.000012          12         1           arch_prctl
    0.00    0.000012          12         1           set_robust_list
    0.00    0.000011          11         1           set_tid_address
  ------ ----------- ----------- --------- --------- ----------------
  100.00    0.962185                 64190         6 total

What a difference!

There's still a lot of other red flags in there; those can be addressed
separately.

This was originally written as I was learning Rust, and I suspect that I
didn't realize that File wasn't buffered at the time.

For the above link: times go from 1.23s pre-change to 0.85s after:

  0.77user 0.44system 0:01.23elapsed 99%CPU (0avgtext+0avgdata 48520maxresident)k
  0inputs+43952outputs (0major+12825minor)pagefaults 0swaps

  0.69user 0.15system 0:00.85elapsed 98%CPU (0avgtext+0avgdata 48396maxresident)k
  0inputs+43952outputs (0major+12823minor)pagefaults 0swaps
main
Mike Gerwitz 2021-08-20 12:11:28 -04:00
parent c9a2ae533f
commit 0a8fb71c1b
1 changed files with 2 additions and 2 deletions

View File

@ -36,7 +36,7 @@ use fxhash::FxBuildHasher;
use petgraph_graphml::GraphMl;
use std::error::Error;
use std::fs;
use std::io::BufReader;
use std::io::{BufReader, BufWriter};
use std::path::{Path, PathBuf};
type LinkerAsg =
@ -234,7 +234,7 @@ fn output_xmle<'a>(
}
let file = fs::File::create(output)?;
let mut xmle_writer = XmleWriter::new(file);
let mut xmle_writer = XmleWriter::new(BufWriter::new(file));
xmle_writer.write(&sorted, name, &relroot)?;
Ok(())