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.
