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

[Pádraig Brady]

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.