Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[openbsd] fiche is very slow locally #14

Closed
jirib opened this issue Aug 25, 2015 · 14 comments
Closed

[openbsd] fiche is very slow locally #14

jirib opened this issue Aug 25, 2015 · 14 comments
Labels

Comments

@jirib
Copy link

jirib commented Aug 25, 2015

It takes 5 secs to do pipe local file to fiche, it's almost equal time while using termbin.com. Any idea?

# sysctl kern.version                                                      
kern.version=OpenBSD 5.8-current (GENERIC.MP) #1253: Fri Aug 21 21:33:17 MDT 2015
    [email protected]:/usr/src/sys/arch/amd64/compile/GENERIC.MP

# grep GH_COMMIT /home/jirib/personal/git/openbsd-mystuff/www/fiche/Makefile 
GH_COMMIT =             a85e04d8160a30c2a6e365b59189842fc5bca670
# time cat /etc/fstab | nc localhost 9999 
http://localhost/cx2j
    0m05.02s real     0m00.00s user     0m00.00s system

And before above was executed tracing of fiche was done...

  8347/-1               1440535952.430622 EMUL  "native"
  8347/1008347 fiche    1440535956.282909 STRU  struct sockaddr { AF_INET, 127.0.0.1:33215 }
  8347/1008347 fiche    1440535956.282916 RET   accept 4
  8347/1008347 fiche    1440535956.282921 CALL  setsockopt(4,SOL_SOCKET,SO_RCVTIMEO,0x7f7fffff55c0,16)
  8347/1008347 fiche    1440535956.282929 RET   setsockopt 0
  8347/1008347 fiche    1440535956.282932 CALL  setsockopt(4,SOL_SOCKET,SO_SNDTIMEO,0x7f7fffff55c0,16)
  8347/1008347 fiche    1440535956.282937 RET   setsockopt 0
  8347/1008347 fiche    1440535956.282947 CALL  __tfork(0x7f7fffff5540,24)
  8347/1008347 fiche    1440535956.282966 STRU  struct __tfork { tcb=0x18dda4c24260, tid=0x18dd9d761b10, stack=0x18de2a2afa90 }
  8347/1008347 fiche    1440535956.282983 RET   __tfork 1026255/0xfa8cf
  8347/1026255 fiche    1440535956.282986 RET   __tfork 0
  8347/1008347 fiche    1440535956.282990 CALL  accept(3,0x7f7fffff55d0,0x7f7fffff55f4)
  8347/1026255 fiche    1440535956.282996 CALL  issetugid()
  8347/1026255 fiche    1440535956.282999 RET   issetugid 0
  8347/1026255 fiche    1440535956.283004 CALL  getpid()
  8347/1026255 fiche    1440535956.283006 RET   getpid 8347/0x209b
  8347/1026255 fiche    1440535956.283007 CALL  clock_gettime(CLOCK_MONOTONIC,0x18de2a2ae730)
  8347/1026255 fiche    1440535956.283011 STRU  struct timespec { 98792<"Jan  2 04:26:32 1970">.341332003 }
  8347/1026255 fiche    1440535956.283013 RET   clock_gettime 0
  8347/1026255 fiche    1440535956.283014 CALL  stat(0x18de12581420,0x18de2a2ae6b0)
  8347/1026255 fiche    1440535956.283017 NAMI  "/etc/resolv.conf"
  8347/1026255 fiche    1440535956.283023 STRU  struct stat { dev=1040, ino=48805, mode=-rw-r--r-- , nlink=1, uid=0<"root">, gid=0<"wheel">, rdev=195823, atime=1440535956<"Aug 25 22:52:36 2015">.266296415, mtime=1440437225<"Aug 24 19:27:05 2015">.293364724, ctime=1440437225<"Aug 24 19:27:05 2015">.293364724, size=74, blocks=4, blksize=16384, flags=0x0, gen=0x0 }
  8347/1026255 fiche    1440535956.283033 RET   stat 0
  8347/1026255 fiche    1440535956.283038 CALL  open(0x18de12581420,0x10000<O_RDONLY|O_CLOEXEC>)
  8347/1026255 fiche    1440535956.283042 NAMI  "/etc/resolv.conf"
  8347/1026255 fiche    1440535956.283045 RET   open 5
  8347/1026255 fiche    1440535956.283049 CALL  fstat(5,0x18de2a2ae550)
  8347/1026255 fiche    1440535956.283052 STRU  struct stat { dev=1040, ino=48805, mode=-rw-r--r-- , nlink=1, uid=0<"root">, gid=0<"wheel">, rdev=195823, atime=1440535956<"Aug 25 22:52:36 2015">.266296415, mtime=1440437225<"Aug 24 19:27:05 2015">.293364724, ctime=1440437225<"Aug 24 19:27:05 2015">.293364724, size=74, blocks=4, blksize=16384, flags=0x0, gen=0x0 }
  8347/1026255 fiche    1440535956.283054 RET   fstat 0
  8347/1026255 fiche    1440535956.283057 CALL  read(5,0x18ddf7576000,0x4000)
  8347/1026255 fiche    1440535956.283068 GIO   fd 5 read 74 bytes
   0000:  23 20 47 65 6e 65 72 61 74 65 64 20 62 79 20 69 77 6e 30 20 64 68 63 6c 69 65 6e 74 0a 73 65 61 72 63 68 20 61 66 74 65 72 62 6f 6f 74 63 7a 2e 77  # Generated by iwn0 dhclient.search afterbootcz.w
   0031:  6c 61 6e 0a 6e 61 6d 65 73 65 72 76 65 72 20 31 32 37 2e 30 2e 30 2e 31 0a                                                                          lan.nameserver 127.0.0.1.
  8347/1026255 fiche    1440535956.283071 RET   read 74/0x4a
  8347/1026255 fiche    1440535956.283073 CALL  read(5,0x18ddf7576000,0x4000)
  8347/1026255 fiche    1440535956.283077 RET   read 0
  8347/1026255 fiche    1440535956.283080 CALL  close(5)
  8347/1026255 fiche    1440535956.283083 RET   close 0
  8347/1026255 fiche    1440535956.283092 CALL  __sysctl(1.10<kern.hostname>,0x18de2a2ae480,0x18de2a2ae460,0,0)
  8347/1026255 fiche    1440535956.283100 RET   __sysctl 0
  8347/1026255 fiche    1440535956.283102 CALL  issetugid()
  8347/1026255 fiche    1440535956.283105 RET   issetugid 0
  8347/1026255 fiche    1440535956.283107 CALL  getpid()
  8347/1026255 fiche    1440535956.283109 RET   getpid 8347/0x209b
  8347/1026255 fiche    1440535956.283110 CALL  clock_gettime(CLOCK_MONOTONIC,0x18de2a2ae760)
  8347/1026255 fiche    1440535956.283113 STRU  struct timespec { 98792<"Jan  2 04:26:32 1970">.341435022 }
  8347/1026255 fiche    1440535956.283117 RET   clock_gettime 0
  8347/1026255 fiche    1440535956.283120 CALL  getpid()
  8347/1026255 fiche    1440535956.283122 RET   getpid 8347/0x209b
  8347/1026255 fiche    1440535956.283124 CALL  clock_gettime(CLOCK_MONOTONIC,0x18de2a2ae760)
  8347/1026255 fiche    1440535956.283127 STRU  struct timespec { 98792<"Jan  2 04:26:32 1970">.341448362 }
  8347/1026255 fiche    1440535956.283128 RET   clock_gettime 0
  8347/1026255 fiche    1440535956.283139 CALL  clock_gettime(CLOCK_MONOTONIC,0x18de2a2ad540)
  8347/1026255 fiche    1440535956.283142 STRU  struct timespec { 98792<"Jan  2 04:26:32 1970">.341464216 }
  8347/1026255 fiche    1440535956.283144 RET   clock_gettime 0
  8347/1026255 fiche    1440535956.283145 CALL  getpid()
  8347/1026255 fiche    1440535956.283147 RET   getpid 8347/0x209b
  8347/1026255 fiche    1440535956.283152 CALL  socket(AF_INET,0x2<SOCK_DGRAM>,0)
  8347/1026255 fiche    1440535956.283156 RET   socket 5
  8347/1026255 fiche    1440535956.283158 CALL  fcntl(5,F_GETFL)
  8347/1026255 fiche    1440535956.283161 RET   fcntl 2
  8347/1026255 fiche    1440535956.283162 CALL  fcntl(5,F_SETFL,0x6<O_RDWR|O_NONBLOCK>)
  8347/1026255 fiche    1440535956.283164 RET   fcntl 0
  8347/1026255 fiche    1440535956.283166 CALL  connect(5,0x18de12582e10,16)
  8347/1026255 fiche    1440535956.283169 STRU  struct sockaddr { AF_INET, 127.0.0.1:53 }
  8347/1026255 fiche    1440535956.283175 RET   connect 0
  8347/1026255 fiche    1440535956.283178 CALL  sendto(5,0x18dda4c26400,0x28,0,0,0)
  8347/1026255 fiche    1440535956.283188 GIO   fd 5 wrote 40 bytes
   0000:  8a 2c 01 00 00 01 00 00 00 00 00 00 01 31 01 30 01 30 03 31 32 37 07 69 6e 2d 61 64 64 72 04 61 72 70 61 00 00 0c 00 01                             .,...........1.0.0.127.in-addr.arpa.....
  8347/1026255 fiche    1440535956.283191 RET   sendto 40/0x28
  8347/1026255 fiche    1440535956.283195 CALL  poll(0x18de2a2af7e0,1,5000)
  8347/1026255 fiche    1440535956.283258 RET   poll 1
  8347/1026255 fiche    1440535956.283279 CALL  recvfrom(5,0x18ddf7575400,0x200,0,0,0)
  8347/1026255 fiche    1440535956.283285 GIO   fd 5 read 121 bytes
   0000:  8a 2c 85 80 00 01 00 01 00 01 00 02 01 31 01 30 01 30 03 31 32 37 07 69 6e 2d 61 64 64 72 04 61 72 70 61 00 00 0c 00 01 c0 0c 00 0c 00 01 00 01 51  .,...........1.0.0.127.in-addr.arpa.............Q
   0031:  80 00 0b 09 6c 6f 63 61 6c 68 6f 73 74 00 c0 0c 00 02 00 01 00 01 51 80 00 02 c0 34 c0 34 00 01 00 01 00 01 51 80 00 04 7f 00 00 01 c0 34 00 1c 00  ....localhost.........Q....4.4......Q........4...
   0062:  01 00 01 51 80 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01                                                                                ...Q...................
  8347/1026255 fiche    1440535956.283287 RET   recvfrom 121/0x79
  8347/1026255 fiche    1440535956.283289 CALL  close(5)
  8347/1026255 fiche    1440535956.283294 RET   close 0
  8347/1026255 fiche    1440535956.283317 CALL  recvfrom(4,0x18de2a2a79e0,0x8000,0x40<MSG_WAITALL>,0,0)
  8347/1026255 fiche    1440535961.286458 GIO   fd 4 read 313 bytes
   0000:  39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 62 20 6e 6f 6e 65 20 73 77 61 70 20 73 77 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e  932b3467fb22696c.b none swap sw.932b3467fb22696c.
   0031:  61 20 2f 20 66 66 73 20 72 77 20 31 20 31 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 68 20 2f 68 6f 6d 65 20 66 66 73 20 72 77 2c 6e 6f  a / ffs rw 1 1.932b3467fb22696c.h /home ffs rw,no
   0062:  64 65 76 2c 6e 6f 73 75 69 64 2c 6e 6f 61 74 69 6d 65 2c 73 6f 66 74 64 65 70 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 64  dev,nosuid,noatime,softdep 1 2.932b3467fb22696c.d
   0093:  20 2f 74 6d 70 20 66 66 73 20 72 77 2c 6e 6f 64 65 76 2c 6e 6f 73 75 69 64 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 66 20   /tmp ffs rw,nodev,nosuid 1 2.932b3467fb22696c.f 
   00c4:  2f 75 73 72 20 66 66 73 20 72 77 2c 6e 6f 64 65 76 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 67 20 2f 75 73 72 2f 6c 6f 63  /usr ffs rw,nodev 1 2.932b3467fb22696c.g /usr/loc
   00f5:  61 6c 20 66 66 73 20 72 77 2c 6e 6f 64 65 76 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 65 20 2f 76 61 72 20 66 66 73 20 72  al ffs rw,nodev 1 2.932b3467fb22696c.e /var ffs r
   0126:  77 2c 6e 6f 64 65 76 2c 6e 6f 73 75 69 64 20 31 20 32 0a                                                                                            w,nodev,nosuid 1 2.
  8347/1026255 fiche    1440535961.286469 RET   recvfrom 313/0x139
  8347/1026255 fiche    1440535961.286482 CALL  mkdir(0x7f7fffff57a8,0755<S_IRUSR|S_IWUSR|S_IXUSR|S_IRGRP|S_IXGRP|S_IROTH|S_IXOTH>)
  8347/1026255 fiche    1440535961.286486 NAMI  "/var/www/fiche/"
  8347/1026255 fiche    1440535961.286503 RET   mkdir -1 errno 17 File exists
  8347/1026255 fiche    1440535961.286504 CALL  mkdir(0x18ddae15eac0,0755<S_IRUSR|S_IWUSR|S_IXUSR|S_IRGRP|S_IXGRP|S_IROTH|S_IXOTH>)
  8347/1026255 fiche    1440535961.286507 NAMI  "/var/www/fiche/cx2j"
  8347/1026255 fiche    1440535961.289748 RET   mkdir 0
  8347/1026255 fiche    1440535961.289758 CALL  open(0x18ddaf9503e0,0x601<O_WRONLY|O_CREAT|O_TRUNC>,0666<S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH>)
  8347/1026255 fiche    1440535961.289762 NAMI  "/var/www/fiche/cx2j/index.txt"
  8347/1026255 fiche    1440535961.290255 RET   open 5
  8347/1026255 fiche    1440535961.290260 CALL  fstat(5,0x18de2a2a77b0)
  8347/1026255 fiche    1440535961.290267 STRU  struct stat { dev=1044, ino=26303, mode=-rw-r--r-- , nlink=1, uid=756<"_fiche">, gid=67<"www">, rdev=0, atime=1440535961<"Aug 25 22:52:41 2015">.286447312, mtime=1440535961<"Aug 25 22:52:41 2015">.286447312, ctime=1440535961<"Aug 25 22:52:41 2015">.286447312, size=0, blocks=0, blksize=16384, flags=0x0, gen=0x0 }
  8347/1026255 fiche    1440535961.290269 RET   fstat 0
  8347/1026255 fiche    1440535961.290273 CALL  write(5,0x18ddf7576000,0x139)
  8347/1026255 fiche    1440535961.290286 GIO   fd 5 wrote 313 bytes
   0000:  39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 62 20 6e 6f 6e 65 20 73 77 61 70 20 73 77 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e  932b3467fb22696c.b none swap sw.932b3467fb22696c.
   0031:  61 20 2f 20 66 66 73 20 72 77 20 31 20 31 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 68 20 2f 68 6f 6d 65 20 66 66 73 20 72 77 2c 6e 6f  a / ffs rw 1 1.932b3467fb22696c.h /home ffs rw,no
   0062:  64 65 76 2c 6e 6f 73 75 69 64 2c 6e 6f 61 74 69 6d 65 2c 73 6f 66 74 64 65 70 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 64  dev,nosuid,noatime,softdep 1 2.932b3467fb22696c.d
   0093:  20 2f 74 6d 70 20 66 66 73 20 72 77 2c 6e 6f 64 65 76 2c 6e 6f 73 75 69 64 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 66 20   /tmp ffs rw,nodev,nosuid 1 2.932b3467fb22696c.f 
   00c4:  2f 75 73 72 20 66 66 73 20 72 77 2c 6e 6f 64 65 76 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 67 20 2f 75 73 72 2f 6c 6f 63  /usr ffs rw,nodev 1 2.932b3467fb22696c.g /usr/loc
   00f5:  61 6c 20 66 66 73 20 72 77 2c 6e 6f 64 65 76 20 31 20 32 0a 39 33 32 62 33 34 36 37 66 62 32 32 36 39 36 63 2e 65 20 2f 76 61 72 20 66 66 73 20 72  al ffs rw,nodev 1 2.932b3467fb22696c.e /var ffs r
   0126:  77 2c 6e 6f 64 65 76 2c 6e 6f 73 75 69 64 20 31 20 32 0a                                                                                            w,nodev,nosuid 1 2.
  8347/1026255 fiche    1440535961.290289 RET   write 313/0x139
  8347/1026255 fiche    1440535961.290291 CALL  close(5)
  8347/1026255 fiche    1440535961.290296 RET   close 0
  8347/1026255 fiche    1440535961.290302 CALL  gettimeofday(0x18de2a2a78c0,0)
  8347/1026255 fiche    1440535961.290305 STRU  struct timeval { 1440535961<"Aug 25 22:52:41 2015">.290305 }
  8347/1026255 fiche    1440535961.290307 RET   gettimeofday 0
  8347/1026255 fiche    1440535961.290324 CALL  write(4,0x18de2a2a7990,0x16)
  8347/1026255 fiche    1440535961.290356 GIO   fd 4 wrote 22 bytes
   0000:  68 74 74 70 3a 2f 2f 6c 6f 63 61 6c 68 6f 73 74 2f 63 78 32 6a 0a                                                                                   http://localhost/cx2j.
  8347/1026255 fiche    1440535961.290374 RET   write 22/0x16
  8347/1026255 fiche    1440535961.290376 CALL  close(4)
  8347/1026255 fiche    1440535961.290398 RET   close 0
  8347/1026255 fiche    1440535961.290406 CALL  __threxit(0x18dd9d761b10)
@solusipse
Copy link
Owner

Can't reproduce this error. Even on OS X I get these:

mac:~ solusipse$ time echo "test" | nc localhost 9999
http://localhost/uwyi

real    0m0.012s
user    0m0.001s
sys 0m0.003s

Maybe it's hard disk related? Try with echo instead of cat? Change fiche's output directory?

@jirib
Copy link
Author

jirib commented Aug 26, 2015

Have you read ktrace output? Anyway, it doesn't seem to be related to I/O as I tried to put output directory in memory (OpenBSD tmpfs).

# time echo "test" | nc 127.0.0.1 9999 
Saved to: /var/www/fiche/davc/index.txt
Wed Aug 26 16:18:24 2015
Client: 127.0.0.1 (localhost)
====================================
http://localhost/davc
    0m05.00s real     0m00.00s user     0m00.01s system

I'm going to compare it with RHEL6...

@jirib
Copy link
Author

jirib commented Aug 26, 2015

Comparison with latest RHEL6... So this issue is OpenBSD related.

# time echo "test" | nc localhost 9999
http://localhost/7yeu

real    0m0.051s
user    0m0.002s
sys     0m0.023s
# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 6.7 (Santiago)

@jirib
Copy link
Author

jirib commented Aug 26, 2015

IIUC the 5 seconds "delay" is here (another try, comments inline):

...
  4000/1029257 fiche    1440600510.127147 CALL  recvfrom(4,0x1bde0a3a7e50,0x8000,0x40<MSG_WAITALL>,0,0)
                                ^^ 
                                 5 secs between calls
                                vv
  4000/1029257 fiche    1440600515.132225 GIO   fd 4 read 5 bytes
   0000:  74 65 73 74 0a                                                                                                                                      test.
  4000/1029257 fiche    1440600515.132233 RET   recvfrom 5
  4000/1029257 fiche    1440600515.132243 CALL  mkdir(0x7f7ffffd6ca8,0755<S_IRUSR|S_IWUSR|S_IXUSR|S_IRGRP|S_IXGRP|S_IROTH|S_IXOTH>)
  4000/1029257 fiche    1440600515.132246 NAMI  "/var/www/fiche/"
...

@solusipse
Copy link
Owner

Could you change timeout.tv_sec = 5; to other value (line 114 in fiche.c) and check if latency time is different?

@jirib
Copy link
Author

jirib commented Aug 26, 2015

It seems you nailed it...

$ grep timeout.tv_sec /home/jirib/openbsd/pobj/fiche-20150504/fiche-a85e04d8160a30c2a6e365b59189842fc5bca670/fiche.c  
    timeout.tv_sec = 15;
$ time echo "test" | nc 127.0.0.1 9999
http://localhost/tuv0
    0m15.00s real     0m00.00s user     0m00.01s system


@solusipse
Copy link
Owner

It seems that on OpenBSD fiche can't detect end of stream and is waiting for timeout to drop a connection. I'll try to reproduce this and find a solution. Thank you.

@jirib
Copy link
Author

jirib commented Aug 27, 2015

man nc on openbsd:

...
     -N      shutdown(2) the network socket after EOF on the input.  Some
             servers require this to finish their work.

...

with -N option it works super faaast ;)

$ time echo "test" | nc -N localhost 9999   
http://localhost/x6v8
    0m00.01s real     0m00.00s user     0m00.01s system

@renaudallard
Copy link
Contributor

The netcat version of OpenBSD does not send an end of stream by default, you need to use the "-N" flag. This functionality doesn't exist on linux netcat, and it seems its default is to send the end of stream.

@solusipse
Copy link
Owner

@renaudallard thank you! I got to do some test because, if I remember correctly, there were some problems with MSG_DONTWAIT. MSG_WAITALL was added in this commit 2d5e5c9.

@solusipse
Copy link
Owner

Thank you! Fixed in: 49ea4c7.

@sbrl
Copy link

sbrl commented Jan 23, 2016

After applying the fix from #31, I don't get this issue.

@solusipse
Copy link
Owner

In #31 we decided to revert 49ea4c7 since it caused some serious problems. I guess we really can't fix issue #14. As @renaudallard noted:

The netcat version of OpenBSD does not send an end of stream by default, you need to use the "-N" flag. This functionality doesn't exist on linux netcat, and it seems its default is to send the end of stream.

Probably the only option is to create a list of supported implementations. We could also think of lowering the timeout rate, but this requires some tests.

@solusipse
Copy link
Owner

I'm closing this, thank you. This can be resolved by using different netcat implementation. See #66 for more details.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants