This is the mail archive of the cygwin@cygwin.com mailing list for the Cygwin project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

possible cygwin bug: delays when using pipes


Seemingly, whenever I use a pipe in bash the cygwin freezes for a long time.
For example:
'echo a | cat' takes about 10 seconds to execute, 'bash -l -i' takes about a
minute.

I am not sure when the problem appeared. Might have been last cygwin dll
release but I am not sure. First time I noticed was running 'bash -l -i'. I
changed the cygwin.bat recently so for a while I thought it was my meddling
but as far as I can see that is not the case. Right now the cygwin is quite
unusable since any non-trivial command line takes a long time to execute.

My startup script:

@echo off

set HOME=D:\DEV\CYGWIN\home\eugene
set TERM=ansi

rem D:
rem chdir \dev\cygwin\bin

IF NOT "x%1" == "x" ( cd %1 ) ELSE ( cd %HOME% )
d:\dev\cygwin\bin\bash --login -i

Here are the results for
strace -f -m thread bash -i -l
of which I can not make out much at all apart from the fact that certain
combination of calls (read_pipe followed WFMO message) takes 10 seconds each
:
 8461    8461 [main] bash 3692 cygthread::cygthread: name sig, id 0xF20
54541   63002 [main] bash 3692 cygthread::cygthread: name proc, id 0xF54
17409   80411 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0x9B0
9713344 9793755 [main] bash 3692 cygthread::detach: WFMO returns 0, id 0x0
 1395 9795150 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
9982585 19777735 [main] bash 3692 cygthread::detach: WFMO returns 1, id
0xD04
10042750 29820485 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
9958336 39778821 [main] bash 3692 cygthread::detach: WFMO returns 1, id
0xD04
  212 39779033 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
 5883 39784916 [main] bash 3692 cygthread::detach: WFMO returns 1, id 0xD04
39658 39824574 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
10007110 49831684 [main] bash 3692 cygthread::detach: WFMO returns 1, id
0xD04
 2207 49833891 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
 5329 49839220 [main] bash 3692 cygthread::detach: WFMO returns 0, id 0xD04
 8461    8461 [main] bash 3692 cygthread::cygthread: name sig, id 0xF20
54541   63002 [main] bash 3692 cygthread::cygthread: name proc, id 0xF54
17409   80411 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0x9B0
9713344 9793755 [main] bash 3692 cygthread::detach: WFMO returns 0, id 0x0
 1395 9795150 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
9982585 19777735 [main] bash 3692 cygthread::detach: WFMO returns 1, id
0xD04
10042750 29820485 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
9958336 39778821 [main] bash 3692 cygthread::detach: WFMO returns 1, id
0xD04
  212 39779033 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
 5883 39784916 [main] bash 3692 cygthread::detach: WFMO returns 1, id 0xD04
39658 39824574 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
10007110 49831684 [main] bash 3692 cygthread::detach: WFMO returns 1, id
0xD04
 2207 49833891 [main] bash 3692 cygthread::cygthread: name read_pipe, id
0xD04
 5329 49839220 [main] bash 3692 cygthread::detach: WFMO returns 0, id 0xD04

Also, when finally in bash, results of 'echo a | strace -f -m syscall,thread
cat'
where the delay is in read_pipe then WMFO pair:
 6287    6287 [main] cat 2432 normalize_posix_path: src /etc/passwd
  745    7032 [main] cat 2432 symlink_info::check: not a symlink
   94    7126 [main] cat 2432 symlink_info::check: 0 = symlink.check
(D:\dev\cygwin\etc\passwd, 0x22F7C8) (0xA)
  522    7648 [main] cat 2432 normalize_posix_path: src /etc/group
  415    8063 [main] cat 2432 symlink_info::check: not a symlink
   78    8141 [main] cat 2432 symlink_info::check: 0 = symlink.check
(D:\dev\cygwin\etc\group, 0x22F7A8) (0xA)
  407    8548 [main] cat 2432 _cygwin_istext_for_stdio:
_cygwin_istext_for_stdio (0)
   57    8605 [main] cat 2432 _cygwin_istext_for_stdio:  _cifs: fd not open
   34    8639 [main] cat 2432 _cygwin_istext_for_stdio:
_cygwin_istext_for_stdio (1)
   33    8672 [main] cat 2432 _cygwin_istext_for_stdio:  _cifs: fd not open
   32    8704 [main] cat 2432 _cygwin_istext_for_stdio:
_cygwin_istext_for_stdio (2)
   31    8735 [main] cat 2432 _cygwin_istext_for_stdio:  _cifs: fd not open
  407    9142 [main] cat 2432 cygthread::cygthread: name sig, id 0xD4C
  704    9846 [main] cat 2432 normalize_posix_path: src /dev/piper
  264   10110 [main] cat 2432 fhandler_base::set_flags: filemode set to
binary
 3083   13193 [main] cat 2432 normalize_posix_path: src
/home/eugene/strace.txt
  481   13674 [main] cat 2432 symlink_info::check: not a symlink
   98   13772 [main] cat 2432 symlink_info::check: 0 = symlink.check
(D:\dev\cygwin\home\eugene\strace.txt, 0x22F488) (0xA)
  191   13963 [main] cat 2432 fhandler_base::set_flags: filemode set to
binary
  177   14140 [main] cat 2432 normalize_posix_path: src /dev/conout
  305   14445 [main] cat 2432 tty_min::set_ctty: attached tty1073741824 sid
2432, pid 2432, tty->pgid 0, tty->sid 2432
 2873   17318 [main] cat 2432 fhandler_base::set_flags: filemode set to
binary
  443   17761 [main] cat 2432 fhandler_console::output_tcsetattr: 0 =
tcsetattr (,A020018) (ENABLE FLAGS 3) (lflag 107 oflag 9)
  322   18083 [main] cat 2432 normalize_posix_path: src
D:\dev\cygwin\home\eugene\strace.txt
  520   18603 [main] cat 2432 symlink_info::check: not a symlink
   91   18694 [main] cat 2432 symlink_info::check: 0 = symlink.check
(D:\dev\cygwin\home\eugene\strace.txt, 0x22F578) (0xA)
  180   18874 [main] cat 2432 fhandler_disk_file::fstat_helper: 0 = fstat (,
0x22FD98) st_atime=3E2409D0 st_size=2238, st_mode=0x81A4, st_ino=-136640046,
sizeof=88
   46   18920 [main] cat 2432 fstat64: 0 = fstat (1, 0x22FD98)
   48   18968 [main] cat 2432 isatty: 0 = isatty (1)
   50   19018 [main] cat 2432 isatty: 0 = isatty (1)
   89   19107 [main] cat 2432 fhandler_base::set_flags: filemode set to
binary
   33   19140 [main] cat 2432 _cygwin_istext_for_stdio:
_cygwin_istext_for_stdio (1)
   35   19175 [main] cat 2432 _cygwin_istext_for_stdio:  _cifs: get_*_binary
   41   19216 [main] cat 2432 setmode_helper: setmode: file was raw now raw
   35   19251 [main] cat 2432 setmode: setmode (1</home/eugene/strace.txt>,
0x10000) returns binary
   38   19289 [main] cat 2432 isatty: 0 = isatty (0)
   34   19323 [main] cat 2432 isatty: 0 = isatty (0)
   85   19408 [main] cat 2432 fhandler_base::set_flags: filemode set to
binary
   33   19441 [main] cat 2432 _cygwin_istext_for_stdio:
_cygwin_istext_for_stdio (0)
   33   19474 [main] cat 2432 _cygwin_istext_for_stdio:  _cifs: fd not disk
file
   34   19508 [main] cat 2432 setmode_helper: setmode: file was raw now raw
   34   19542 [main] cat 2432 setmode: setmode (0</dev/piper>, 0x10000)
returns binary
   39   19581 [main] cat 2432 normalize_posix_path: src \dev\piper
  195   19776 [main] cat 2432 cwdstuff::get: (D:\dev\cygwin\home\eugene) =
cwdstuff::get (0x22F288, 260, 0, 0), errno 0
  789   20565 [main] cat 2432 geterrno_from_win_error: windows error 2 ==
errno 2
  248   20813 [main] cat 2432 geterrno_from_win_error: windows error 2 ==
errno 2
   43   20856 [main] cat 2432 symlink_info::check: 0 = symlink.check
(d:\dev\piper, 0x22F578) (0x22)
  222   21078 [main] cat 2432 symlink_info::check: not a symlink
   49   21127 [main] cat 2432 symlink_info::check: 0 = symlink.check
(d:\dev, 0x22F578) (0x22)
  148   21275 [main] cat 2432 fstat64: 0 = fstat (0, 0x22FD98)
  101   21376 [main] cat 2432 readv: readv (0, 0x22FD88, 1) blocking,
sigcatchers 0
  258   21634 [main] cat 2432 cygthread::cygthread: name read_pipe, id 0xA78
10639163 10660797 [main] cat 2432 cygthread::detach: WFSO returns 0, id
0xA78
  247 10661044 [main] cat 2432 readv: 2 = readv (0, 0x22FD88, 1), errno 0
a
  185 10661229 [main] cat 2432 readv: readv (0, 0x22FD88, 1) blocking,
sigcatchers 0
   44 10661273 [main] cat 2432 cygthread::cygthread: name read_pipe, id
0xA78
  118 10661391 [main] cat 2432 cygthread::detach: WFSO returns 0, id 0xA78
   83 10661474 [main] cat 2432 readv: 0 = readv (0, 0x22FD88, 1), errno 0
   86 10661560 [main] cat 2432 close: close (0)
   36 10661596 [main] cat 2432 fhandler_base::close: closing '/dev/piper'
handle 0x8C
   50 10661646 [main] cat 2432 close: 0 = close (0)
   60 10661706 [main] cat 2432 do_exit: do_exit (0)
   46 10661752 [main] cat 2432 void: 0x0 = signal (20, 0x1)
   37 10661789 [main] cat 2432 void: 0x0 = signal (1, 0x1)
   35 10661824 [main] cat 2432 void: 0x0 = signal (2, 0x1)
   34 10661858 [main] cat 2432 void: 0x0 = signal (3, 0x1)
   35 10661893 [main] cat 2432 fhandler_base::close: closing
'/home/eugene/strace.txt' handle 0x700
  271 10662164 [main] cat 2432 __to_clock_t: dwHighDateTime 0, dwLowDateTime
312500
   42 10662206 [main] cat 2432 __to_clock_t: total 00000000 0000001F
   38 10662244 [main] cat 2432 __to_clock_t: dwHighDateTime 0, dwLowDateTime
312500
   36 10662280 [main] cat 2432 __to_clock_t: total 00000000 0000001F

I have attached the cygsheck -s -v -r output.
I hope someone can shed some light on my situation.

Attachment: cygcheck-s-v-r.txt
Description: Text document

--
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple
Bug reporting:         http://cygwin.com/bugs.html
Documentation:         http://cygwin.com/docs.html
FAQ:                   http://cygwin.com/faq/

Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]