Bug 802109

Summary: libguestfs uses putc on stderr, results in many individual 1 byte writes of debug messages
Product: [Community] Virtualization Tools Reporter: Richard W.M. Jones <rjones>
Component: libguestfsAssignee: Richard W.M. Jones <rjones>
Status: CLOSED UPSTREAM QA Contact:
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: mbooth, meyering, virt-maint
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-03-13 09:28:01 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Richard W.M. Jones 2012-03-11 11:19:48 UTC 
Description of problem:

Since fixing bug 731744, when writing out debug and trace
messages, we write them out byte-by-byte using 'putc' (because
we want to escape non-printing characters).  Unfortunately
since these messages are sent to stderr, and stderr defaults
to unbuffered, this means each message is written out as a
series of 1 byte write system calls.

Try:
strace -o /tmp/log libguestfs-test-tool

and examine the log file (/tmp/log).  You will see lots
of system calls like this:

write(2, "libguestfs: ", 12)            = 12
write(2, "n", 1)                        = 1
write(2, "e", 1)                        = 1
write(2, "w", 1)                        = 1
write(2, " ", 1)                        = 1
write(2, "g", 1)                        = 1
write(2, "u", 1)                        = 1
write(2, "e", 1)                        = 1
write(2, "s", 1)                        = 1
write(2, "t", 1)                        = 1
write(2, "f", 1)                        = 1
write(2, "s", 1)                        = 1
write(2, " ", 1)                        = 1
write(2, "h", 1)                        = 1
write(2, "a", 1)                        = 1
write(2, "n", 1)                        = 1
write(2, "d", 1)                        = 1
write(2, "l", 1)                        = 1
write(2, "e", 1)                        = 1

Try also this test program:

  #include <stdio.h>
  #include <stdlib.h>
  
  int
  main ()
  {
    FILE *fp = stderr;
    /* FILE *fp = stdout; */
  
    /* setlinebuf (fp); */
  
    fputc ('h', fp);
    fputc ('e', fp);
    fputc ('l', fp);
    fputc ('l', fp);
    fputc ('o', fp);
    fputc ('\n', fp);
  
    exit (EXIT_SUCCESS);
  }

and notice the effect of uncommenting the 'setlinebuf'
line.

We could fix this by setting line buffering on stderr,
but that's not very friendly.  We could also change the
code so it sends groups of printable bytes to stderr
together instead of sending them byte at a time using
putc.

Version-Release number of selected component (if applicable):

libguestfs 1.17.14
Comment 1 Richard W.M. Jones 2012-03-11 11:20:34 UTC 
CC to Jim Meyering.

Any comment on the right way to fix (or ignore?) this problem?
Comment 2 Jim Meyering 2012-03-11 15:13:35 UTC 
Hi Rich,
I presume you don't want to allocate memory, otherwise it'd be trivial:
write the escaped bytes into that buffer and then print the result
with fwrite.

A compromise is to identify contiguous bytes that will not
be escaped and print them using fwrite.  Then handle the
presumably few escapables, then look for more contiguous
unescapables, etc:

#include <stdio.h>
#include <string.h>

static char const *
print_to_first_quotable (char const *p0, char const *end)
{
  int quoted = 0;
  char const *p = p0;
  while (p < end)
    {
      switch (*p)
	{
	case '\0': quoted = '0'; goto done;
	case '\a': quoted = 'a'; goto done;
	case '\b': quoted = 'b'; goto done;
	case '\f': quoted = 'f'; goto done;
	case '\n': quoted = 'n'; goto done;
	case '\r': quoted = 'r'; goto done;
	case '\t': quoted = 't'; goto done;
	case '\v': quoted = 'v'; goto done;

	default:
	  p++;
	  break;
	}
    }

 done:
  fwrite (p0, 1, p - p0, stderr);
  if (quoted)
    {
      fputc ('\\', stderr);
      fputc (quoted, stderr);
    }

  return p + 1;
}

int
main (int argc, char **argv)
{
  if (argc < 2)
    return 99;
  char const *p = argv[1];
  char const *end = p + strlen (p);
  while (p < end)
    {
      p = print_to_first_quotable (p, end);
    }
  return 0;
}

=======================

If you care about the syscall-per-backslash+escaped byte,
you could put the two of them in a 2-byte buffer and save half
of the fputc calls.  If you care about strings of two or more
escapables, add a small local buffer of length say 10-20,
and handle sequences of escapables (up to half of that length)
the same way.
Comment 3 Richard W.M. Jones 2012-03-11 20:17:21 UTC 
Patch posted:
https://www.redhat.com/archives/libguestfs/2012-March/msg00057.html