GNU bug report logs - #14174
BUG REP: tee takes an annoyingly long time in some system.

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 14174 in the body.
You can then email your comments to 14174 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: "Gao, Jie (Kyrie, HPIT-DS-CDC)" <jie.gao <at> hp.com>
To: "bug-coreutils <at> gnu.org" <bug-coreutils <at> gnu.org>
Subject: BUG REP: tee takes an annoyingly long time in some system.
Date: Wed, 10 Apr 2013 09:48:08 +0000

[Message part 1 (text/plain, inline)]

Hello sir,

Not sure if it is tee's problem. Tee works well in my workstation, but it will take a long time on cluster. See the example below. Could you if possible show me the reason why tee spends so long time while it is working on cluster?

This simple tests below illustrate how rep_age can take 30 times longer than necessary:

1.     Without tee @3 seconds
/home/sqdev16> time echo '
> SET TRANSACTION ISOLATION LEVEL READ COMMITTED, READ WRITE, NO ROLLBACK OFF, MULTI COMMIT ON;
> DELETE WITH MULTI COMMIT FROM manageability.instance_repository.problem_instance_table
>   WHERE (gen_ts_lct) < ((CURRENT_TIMESTAMP) - CAST(CAST(0 AS INTEGER)  AS INTERVAL HOUR(2))); ' | sqlci
>>>>
--- SQL operation complete.
>>+>
--- 0 row(s) deleted.
>>

End of MXCI Session


real    0m3.354s
user    0m0.184s
sys     0m0.099s

2.     With tee @ 1 minute 46 seconds:
/home/sqdev16> time echo '
> SET TRANSACTION ISOLATION LEVEL READ COMMITTED, READ WRITE, NO ROLLBACK OFF, MULTI COMMIT ON;
> DELETE WITH MULTI COMMIT FROM manageability.instance_repository.problem_instance_table
>   WHERE (gen_ts_lct) < ((CURRENT_TIMESTAMP) - CAST(CAST(0 AS INTEGER)  AS INTERVAL HOUR(2))); ' | sqlci | tee -a junk
>>>>
--- SQL operation complete.
>>+>
--- 0 row(s) deleted.
>>

End of MXCI Session



real    1m45.969s
user    0m0.180s
sys     0m0.093s

Thanks,
Jie


Gao, Jie (Kyrie)
BIP, DS CDC, HPIT
*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-*-
Email: jie.gao <at> hp.com

[Message part 2 (text/html, inline)]

Message #8 received at 14174 <at> debbugs.gnu.org (full text, mbox):

From: Bernhard Voelker <mail <at> bernhard-voelker.de>
To: "Gao, Jie (Kyrie, HPIT-DS-CDC)" <jie.gao <at> hp.com>
Cc: 14174 <at> debbugs.gnu.org
Subject: Re: bug#14174: BUG REP: tee takes an annoyingly long time in some
	system.
Date: Thu, 11 Apr 2013 11:20:52 +0200

tag 14174 + moreinfo
close 14174
thanks

On 04/10/2013 11:48 AM, Gao, Jie (Kyrie, HPIT-DS-CDC) wrote:
> Hello sir,
> 
> Not sure if it is tee's problem. Tee works well in my workstation, but it will take
> a long time on cluster. See the example below. Could you if possible show me the
> reason why tee spends so long time while it is working on cluster?

Thank you for the report.
However, you can imagine that we have problems to reproduce this issue.

First of all, what do you mean by "is working on cluster"?


> 2.     With tee @ 1 minute 46 seconds:
> /home/sqdev16> time echo '
>> SET TRANSACTION ISOLATION LEVEL READ COMMITTED, READ WRITE, NO ROLLBACK OFF, MULTI COMMIT ON;
>> DELETE WITH MULTI COMMIT FROM manageability.instance_repository.problem_instance_table
>>   WHERE (gen_ts_lct) < ((CURRENT_TIMESTAMP) - CAST(CAST(0 AS INTEGER)  AS INTERVAL HOUR(2))); ' | sqlci | tee -a junk
>>>>>
> --- SQL operation complete.
>>> +>
> --- 0 row(s) deleted.
>>>
> 
> End of MXCI Session
> 
> real    1m45.969s
> user    0m0.180s
> sys     0m0.093s

What's the output of sqlci? Can you redirect it to a file and use that
as input for tee? Does that make a difference?
  ... | sqlci > file
  cat file | time tee -a junk

Can you provide strace output with timing information?
  ... | strace -tt tee -a junk

Another possibility: writing to 'junk' may somehow be blocked during
that run. Are there such timing difference between
   ... | sqlci > /dev/null
   ... | sqlci > junk2              # a new file / truncating
   ... | sqlci >> junk
   ... | sqlci > /tmp/junk          # i.e. a local file system
   ... | sqlci | tee /dev/null
   ... | sqlci | tee -a /tmp/junk   # i.e. a local file system
?

And finally, what version of tee are you using ("tee --version")?
Is it self-compiled or did it come with your distribution (which may
have added patches on top of the upstream version)?

Have a nice day,
Berny

Message #11 received at 14174 <at> debbugs.gnu.org (full text, mbox):

From: Pádraig Brady <P <at> draigBrady.com>
To: "Gao, Jie (Kyrie, HPIT-DS-CDC)" <jie.gao <at> hp.com>
Cc: 14174 <at> debbugs.gnu.org
Subject: Re: bug#14174: BUG REP: tee takes an annoyingly long time in some
	system.
Date: Thu, 11 Apr 2013 11:00:13 +0100

Bringing back on list.
I didn't intend to take off list sorry.
Details below...

On 04/11/2013 06:57 AM, Gao, Jie (Kyrie, HPIT-DS-CDC) wrote:
> On 04/10/2013 09:53 PM, Pádraig Brady wrote:
> > On 04/10/2013 10:48 AM, Gao, Jie (Kyrie, HPIT-DS-CDC) wrote:
> >> Hello sir,
> >>
> >> Not sure if it is tee's problem. Tee works well in my workstation, but it will take a long time on cluster. See the example below. Could you if possible show me the reason why tee spends so long time while it is working on cluster?
> >>
> >> This simple tests below illustrate how rep_age can take 30 times longer than necessary:
> >>
> >> 1.     Without tee @3 seconds
> >> /home/sqdev16> time echo '
> >>> SET TRANSACTION ISOLATION LEVEL READ COMMITTED, READ WRITE, NO ROLLBACK OFF, MULTI COMMIT ON;
> >>> DELETE WITH MULTI COMMIT FROM manageability.instance_repository.problem_instance_table
> >>>   WHERE (gen_ts_lct) < ((CURRENT_TIMESTAMP) - CAST(CAST(0 AS INTEGER)  AS INTERVAL HOUR(2))); ' | sqlci
> >>>>>>
> >> --- SQL operation complete.
> >>>> +>
> >> --- 0 row(s) deleted.
> >>>>
> >>
> >> End of MXCI Session
> >>
> >>
> >> real    0m3.354s
> >> user    0m0.184s
> >> sys     0m0.099s
> >>
> >> 2.     With tee @ 1 minute 46 seconds:
> >> /home/sqdev16> time echo '
> >>> SET TRANSACTION ISOLATION LEVEL READ COMMITTED, READ WRITE, NO ROLLBACK OFF, MULTI COMMIT ON;
> >>> DELETE WITH MULTI COMMIT FROM manageability.instance_repository.problem_instance_table
> >>>   WHERE (gen_ts_lct) < ((CURRENT_TIMESTAMP) - CAST(CAST(0 AS INTEGER)  AS INTERVAL HOUR(2))); ' | sqlci | tee -a junk
> >>>>>>
> >> --- SQL operation complete.
> >>>> +>
> >> --- 0 row(s) deleted.
> >>>>
> >>
> >> End of MXCI Session
> >>
> >> real    1m45.969s
> >> user    0m0.180s
> >> sys     0m0.093s
> >
> > So it's probably not tee's issue.
> > Tee has a simple main loop that synchronously reads stdin and writes to files and stdout.
> > Now there is little data being generated there so it's unlikely a buffering issue
> > (which you could solve by putting some async buffering util in the pipeline
> > before tee (like pv for example)).
> >
> > It seems to me that access to the junk file is taking the time?
> > How long does it take for example if you just .... | sqlci >> junk
> >
> > You could use strace to see where time time is spent: ... | sqlci | strace -rT tee -a junk
>
> Hello Pádraig,
> I'd like to show you the result I test today. Please have a look. Thanks.
>
> 1.Directly save it to temp file
>
> $ time echo 'SQL...;' | sqlci>>temp
>
> real    0m3.344s
> user    0m0.159s
> sys     0m0.087s
>
>
> 2.with tee again
>
> $ time echo 'SQL...;' | sqlci | tee -a temp
>>>>>
> --- SQL operation complete.
>>>
> --- 1 row(s) deleted.
>>>
>
> End of MXCI Session
>
>
> real    1m43.853s
> user    0m0.159s
> sys     0m0.128s
>
> 3.with strace -o out -rT tee -a junk;cat out
>
>      0.000058 open("temp", O_WRONLY|O_CREAT|O_APPEND, 0666) = 3 <0.000019>
>      0.000048 fstat(3, {st_mode=S_IFREG|0640, st_size=636, ...}) = 0 <0.000011>
>      0.000056 lseek(3, 636, SEEK_SET)   = 636 <0.000010>

>      0.000047 read(0, "Hewlett-Packard NonStop(TM) SQL/"..., 8192) = 129 <0.234176>
>      0.234237 write(1, "Hewlett-Packard NonStop(TM) SQL/"..., 129) = 129 <0.000017>
>      0.000039 write(3, "Hewlett-Packard NonStop(TM) SQL/"..., 129) = 129 <0.000016>
>      0.000036 read(0, ">>>>", 8192)     = 4 <0.492161>
>      0.492338 write(1, ">>>>", 4)       = 4 <0.000053>
>      0.000107 write(3, ">>>>", 4)       = 4 <0.000030>
>      0.000073 read(0, "\n--- SQL operation complete.\n>>", 8192) = 31 <0.001297>
>      0.001338 write(1, "\n--- SQL operation complete.\n>>", 31) = 31 <0.000013>
>      0.000038 write(3, "\n--- SQL operation complete.\n>>", 31) = 31 <0.000012>
>      0.000035 read(0, "\n--- 0 row(s) deleted.\n", 8192) = 23 <19.722140>
>     19.722228 write(1, "\n--- 0 row(s) deleted.\n", 23) = 23 <0.000030>
>      0.000080 write(3, "\n--- 0 row(s) deleted.\n", 23) = 23 <0.094912>
>      0.095704 read(0, ">>", 8192)       = 2 <0.000015>
>      0.000059 write(1, ">>", 2)         = 2 <0.000018>
>      0.000049 write(3, ">>", 2)         = 2 <0.114997>
>      0.115062 read(0, "\n\nEnd of MXCI Session\n\n", 8192) = 23 <0.000014>
>      0.000062 write(1, "\n\nEnd of MXCI Session\n\n", 23) = 23 <0.000021>
>      0.000079 write(3, "\n\nEnd of MXCI Session\n\n", 23) = 23 <0.000144>
>      0.000190 read(0, "", 8192)         = 0 <104.552230>
>    104.616062 close(3)                  = 0 <0.000082>  <----spend a long time in closing??
>      0.000178 close(0)                  = 0 <0.000017>
>      0.000069 close(1)                  = 0 <0.000017>
>      0.000059 close(2)                  = 0 <0.000016>
>      0.035280 exit_group(0)             = ?
>
>
> It seems that close(3) will take a long time. Um..I can solve this problem by using sqlci log instead. But if I could know the root cause why tee cannot close fast on cluster, I would be grateful to you.

So tee is spending time in read() waiting for data from stdin,
and this doesn't happen when writing to file.
So I can only conclude that sqlci is doing something weird with pipes.
Is it messing with non blocking I/O, pipe capacity and timers?
I presume you've have the same issue with: ... sqlci | cat >> temp

thanks,
Pádraig.

Message #14 received at 14174 <at> debbugs.gnu.org (full text, mbox):

From: Assaf Gordon <assafgordon <at> gmail.com>
Cc: 14174 <at> debbugs.gnu.org
Subject: Re: bug#14174: BUG REP: tee takes an annoyingly long time in some
 system.
Date: Thu, 18 Oct 2018 18:08:30 -0600

tags 14174 moreinfo
close 14174
thanks

(triaging old bugs)

On 11/04/13 04:00 AM, Pádraig Brady wrote:
> [...]
> So tee is spending time in read() waiting for data from stdin,
> and this doesn't happen when writing to file.
> So I can only conclude that sqlci is doing something weird with pipes.
> Is it messing with non blocking I/O, pipe capacity and timers?
> I presume you've have the same issue with: ... sqlci | cat >> temp
> 


With no further follow-ups in 5 years, I'm closing this bug.

-assaf

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.