Slowness of http_open/3
|
View:
New views
15 Messages
—
Rating Filter:
Alert me
|
 |
Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
Hi,
I'm experiencing a great deal of slowness with http_open/3 running SWI-Prolog (Multi-threaded, 32 bits, Version 5.6.52) under Mac Os X (10.5.2). This is instantaneous: ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', In, []). In = '$stream'(791008). This too: ?- load_xml_file('assets/examples/test.xml',Struct). Struct = [element(a, [], [element(b, [], [c])])]. But this takes about 5 seconds! ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', In, []), load_xml_file(In,Struct), close(In). In = '$stream'(789512), Struct = [element(a, [], [element(b, [], [c])])]. Does anybody have a clue of what is causing this? Best regards, Torbjörn _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Jan Wielemaker
::
Rate this Message:
On Tuesday 20 May 2008 11:03, Torbjörn Lager wrote:
> Hi, > > I'm experiencing a great deal of slowness with http_open/3 running > SWI-Prolog (Multi-threaded, 32 bits, Version 5.6.52) under Mac Os X > (10.5.2). > > This is instantaneous: > > ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', In, > []). In = '$stream'(791008). > > This too: > > ?- load_xml_file('assets/examples/test.xml',Struct). > Struct = [element(a, [], [element(b, [], [c])])]. > > But this takes about 5 seconds! > > ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', > In, []), load_xml_file(In,Struct), close(In). > In = '$stream'(789512), > Struct = [element(a, [], [element(b, [], [c])])]. > > Does anybody have a clue of what is causing this? Interesting. I tried this on 64-bit Linux: :- use_module(library(http/http_open)). :- use_module(library(sgml)). t(Data) :- http_open('http://localhost/jan/rdfs.rdfs', In, []), load_xml_file(In, Data), close(In). Server: apache. rdfs.rdfs is a 10Kbytes XML file. Elapsed time is 1.3 milliseconds (0.13 sec to do this 100 times). Could it be the server? What happens if you get the file using wget or similar? Cheers --- Jan _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
Jan,
I tried: dhcp-22:~ lager$ curl http://localhost:5000/pages/assets/examples/test.xml and that too is instantaneous. I have'nt tried it yet, but I get the impression that I could build my own http_open using the http/http_client library. Perhaps I should try that? Could that make a difference? - Torbjörn On Tue, May 20, 2008 at 11:26 AM, Jan Wielemaker <wielemak@...> wrote: > On Tuesday 20 May 2008 11:03, Torbjörn Lager wrote: >> Hi, >> >> I'm experiencing a great deal of slowness with http_open/3 running >> SWI-Prolog (Multi-threaded, 32 bits, Version 5.6.52) under Mac Os X >> (10.5.2). >> >> This is instantaneous: >> >> ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', In, >> []). In = '$stream'(791008). >> >> This too: >> >> ?- load_xml_file('assets/examples/test.xml',Struct). >> Struct = [element(a, [], [element(b, [], [c])])]. >> >> But this takes about 5 seconds! >> >> ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', >> In, []), load_xml_file(In,Struct), close(In). >> In = '$stream'(789512), >> Struct = [element(a, [], [element(b, [], [c])])]. >> >> Does anybody have a clue of what is causing this? > > Interesting. I tried this on 64-bit Linux: > > :- use_module(library(http/http_open)). > :- use_module(library(sgml)). > > t(Data) :- > http_open('http://localhost/jan/rdfs.rdfs', In, []), > load_xml_file(In, Data), close(In). > > Server: apache. rdfs.rdfs is a 10Kbytes XML file. Elapsed time is 1.3 > milliseconds (0.13 sec to do this 100 times). > > Could it be the server? What happens if you get the file using wget > or similar? > > Cheers --- Jan > > _______________________________________________ > SWI-Prolog mailing list > SWI-Prolog@... > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog > SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Jan Wielemaker
::
Rate this Message:
On Tuesday 20 May 2008 12:06, Torbjörn Lager wrote:
> Jan, > I tried: > > dhcp-22:~ lager$ curl > http://localhost:5000/pages/assets/examples/test.xml > > and that too is instantaneous. > > I have'nt tried it yet, but I get the impression that I could build my > own http_open using the http/http_client library. Perhaps I should try > that? Could that make a difference? http_client does more complicated things, but ultimately uses the same socket layer as http_open/3. So, they most likely behave the same (might be worth testing though) and it is easier to debug http_open/2. It might be related to stream buffering. I recently found out some of the packages use unbuffered streams, the socket library appears to be one of them. That doesn't appear to kill performance on Linux too much but it might be a problem on MacOS. Could you try this: :- use_module(library(http/http_open)). :- use_module(library(sgml)). t(Data) :- http_open('http://localhost:5000/pages/assets/examples/test.xml', In, []), set_stream(In, buffer(full)), load_xml_file(In, Data), close(In). Cheers --- Jan > > - Torbjörn > > > On Tue, May 20, 2008 at 11:26 AM, Jan Wielemaker > > <wielemak@...> wrote: > > On Tuesday 20 May 2008 11:03, Torbjörn Lager wrote: > >> Hi, > >> > >> I'm experiencing a great deal of slowness with http_open/3 running > >> SWI-Prolog (Multi-threaded, 32 bits, Version 5.6.52) under Mac Os X > >> (10.5.2). > >> > >> This is instantaneous: > >> > >> ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', > >> In, []). In = '$stream'(791008). > >> > >> This too: > >> > >> ?- load_xml_file('assets/examples/test.xml',Struct). > >> Struct = [element(a, [], [element(b, [], [c])])]. > >> > >> But this takes about 5 seconds! > >> > >> ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', > >> In, []), load_xml_file(In,Struct), close(In). > >> In = '$stream'(789512), > >> Struct = [element(a, [], [element(b, [], [c])])]. > >> > >> Does anybody have a clue of what is causing this? > > > > Interesting. I tried this on 64-bit Linux: > > :- use_module(library(http/http_open)). > > :- use_module(library(sgml)). > > > > t(Data) :- > > http_open('http://localhost/jan/rdfs.rdfs', In, []), > > load_xml_file(In, Data), close(In). > > > > Server: apache. rdfs.rdfs is a 10Kbytes XML file. Elapsed time is 1.3 > > milliseconds (0.13 sec to do this 100 times). > > > > Could it be the server? What happens if you get the file using wget > > or similar? > > > > Cheers --- Jan > > > > _______________________________________________ > > SWI-Prolog mailing list > > SWI-Prolog@... > > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog > > _______________________________________________ > SWI-Prolog mailing list > SWI-Prolog@... > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
I tried
> :- use_module(library(http/http_open)). > :- use_module(library(sgml)). > > t(Data) :- > http_open('http://localhost:5000/pages/assets/examples/test.xml', In, []), > set_stream(In, buffer(full)), > load_xml_file(In, Data), > close(In). and it showed the same behaviour. Note that the size of the file that I'm testing with is VERY small (contains <a><b>c</b></a> only). So could that really be a buffering problem? When testing with bigger (but still ot BIG files I get the impression that the delay is basically independent of the size of the input. And it seems to be exacly 5 seconds (+ a few ms) each time. Could it be (the default setting for) a timeout of some kind that is playing tricks on us? - Torbjörn - Torbjörn On Tue, May 20, 2008 at 1:32 PM, Jan Wielemaker <wielemak@...> wrote: > On Tuesday 20 May 2008 12:06, Torbjörn Lager wrote: >> Jan, >> I tried: >> >> dhcp-22:~ lager$ curl >> http://localhost:5000/pages/assets/examples/test.xml >> >> and that too is instantaneous. >> >> I have'nt tried it yet, but I get the impression that I could build my >> own http_open using the http/http_client library. Perhaps I should try >> that? Could that make a difference? > > http_client does more complicated things, but ultimately uses the same > socket layer as http_open/3. So, they most likely behave the same (might > be worth testing though) and it is easier to debug http_open/2. > > It might be related to stream buffering. I recently found out some of > the packages use unbuffered streams, the socket library appears to be > one of them. That doesn't appear to kill performance on Linux too much > but it might be a problem on MacOS. Could you try this: > > :- use_module(library(http/http_open)). > :- use_module(library(sgml)). > > t(Data) :- > http_open('http://localhost:5000/pages/assets/examples/test.xml', In, []), > set_stream(In, buffer(full)), > load_xml_file(In, Data), > close(In). > > Cheers --- Jan > > >> >> - Torbjörn >> >> >> On Tue, May 20, 2008 at 11:26 AM, Jan Wielemaker >> >> <wielemak@...> wrote: >> > On Tuesday 20 May 2008 11:03, Torbjörn Lager wrote: >> >> Hi, >> >> >> >> I'm experiencing a great deal of slowness with http_open/3 running >> >> SWI-Prolog (Multi-threaded, 32 bits, Version 5.6.52) under Mac Os X >> >> (10.5.2). >> >> >> >> This is instantaneous: >> >> >> >> ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', >> >> In, []). In = '$stream'(791008). >> >> >> >> This too: >> >> >> >> ?- load_xml_file('assets/examples/test.xml',Struct). >> >> Struct = [element(a, [], [element(b, [], [c])])]. >> >> >> >> But this takes about 5 seconds! >> >> >> >> ?- http_open('http://localhost:5000/pages/assets/examples/test.xml', >> >> In, []), load_xml_file(In,Struct), close(In). >> >> In = '$stream'(789512), >> >> Struct = [element(a, [], [element(b, [], [c])])]. >> >> >> >> Does anybody have a clue of what is causing this? >> > >> > Interesting. I tried this on 64-bit Linux: >> > :- use_module(library(http/http_open)). >> > :- use_module(library(sgml)). >> > >> > t(Data) :- >> > http_open('http://localhost/jan/rdfs.rdfs', In, []), >> > load_xml_file(In, Data), close(In). >> > >> > Server: apache. rdfs.rdfs is a 10Kbytes XML file. Elapsed time is 1.3 >> > milliseconds (0.13 sec to do this 100 times). >> > >> > Could it be the server? What happens if you get the file using wget >> > or similar? >> > >> > Cheers --- Jan >> > >> > _______________________________________________ >> > SWI-Prolog mailing list >> > SWI-Prolog@... >> > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog >> >> _______________________________________________ >> SWI-Prolog mailing list >> SWI-Prolog@... >> https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog > > _______________________________________________ > SWI-Prolog mailing list > SWI-Prolog@... > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog > SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Jan Wielemaker
::
Rate this Message:
On Tuesday 20 May 2008 15:04, Torbjörn Lager wrote:
> I tried > > > :- use_module(library(http/http_open)). > > :- use_module(library(sgml)). > > > > t(Data) :- > > http_open('http://localhost:5000/pages/assets/examples/test.xml', > > In, []), set_stream(In, buffer(full)), > > load_xml_file(In, Data), > > close(In). > > and it showed the same behaviour. > > Note that the size of the file that I'm testing with is VERY small > (contains <a><b>c</b></a> only). So could that really be a buffering > problem? When testing with bigger (but still ot BIG files I get the Indeed unlikely. > impression that the delay is basically independent of the size of the > input. And it seems to be exacly 5 seconds (+ a few ms) each time. > Could it be (the default setting for) a timeout of some kind that is > playing tricks on us? One gets the impression. What happens on ?- time(t(X))? What is the percentage CPU time? In my test this was almost 100% (dual core, so the server uses the other core). Next step is to replace your load_xml_file(In, Data) by a simple read_data(In) :- repeat, time(get_byte(In, B0)), B0 == -1, !. and see what happens? Cheers --- Jan _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
Here's what happens:
:- use_module(library(http/http_open)). :- use_module(library(sgml)). t(Data) :- http_open('http://localhost:5001/pages/assets/examples/test.xml', In, []), read_data(In), close(In). read_data(In) :- repeat, time(get_byte(In, B0)), B0 == -1, !. ?- time(t(_)). % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) % 1 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) % 2,080 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) true. - Torbjörn On Tue, May 20, 2008 at 3:42 PM, Jan Wielemaker <wielemak@...> wrote: > On Tuesday 20 May 2008 15:04, Torbjörn Lager wrote: >> I tried >> >> > :- use_module(library(http/http_open)). >> > :- use_module(library(sgml)). >> > >> > t(Data) :- >> > http_open('http://localhost:5000/pages/assets/examples/test.xml', >> > In, []), set_stream(In, buffer(full)), >> > load_xml_file(In, Data), >> > close(In). >> >> and it showed the same behaviour. >> >> Note that the size of the file that I'm testing with is VERY small >> (contains <a><b>c</b></a> only). So could that really be a buffering >> problem? When testing with bigger (but still ot BIG files I get the > > Indeed unlikely. > >> impression that the delay is basically independent of the size of the >> input. And it seems to be exacly 5 seconds (+ a few ms) each time. >> Could it be (the default setting for) a timeout of some kind that is >> playing tricks on us? > > One gets the impression. What happens on ?- time(t(X))? What is the > percentage CPU time? In my test this was almost 100% (dual core, so the > server uses the other core). > > Next step is to replace your load_xml_file(In, Data) by a simple > > read_data(In) :- > repeat, > time(get_byte(In, B0)), > B0 == -1, !. > > and see what happens? > > Cheers --- Jan > > _______________________________________________ > SWI-Prolog mailing list > SWI-Prolog@... > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog > SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Jan Wielemaker
::
Rate this Message:
On Tuesday 20 May 2008 16:31, Torbjörn Lager wrote:
> Here's what happens: > :- use_module(library(http/http_open)). > :- use_module(library(sgml)). > > t(Data) :- > http_open('http://localhost:5001/pages/assets/examples/test.xml', > In, []), > read_data(In), > close(In). > > read_data(In) :- > repeat, > time(get_byte(In, B0)), > B0 == -1, !. > > ?- time(t(_)). > % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) > % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) > % 1 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) > % 2,080 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) > true. Ok. So, somehow detecting end-of-file takes very long!? Typically, it is now time to run a system call tracer to see what happens when. I don't recall what this is called on MacOS (or even whether it exists as default component), but typically they go by the name 'strace', 'truss', 'trace' or something sinmilar. Now run "% strace swipl <options>" and your program. I think there is by default no timing information displayed, but you should notice a call blocking 5 seconds. Can you find that call? If its gets too confusing on your terminal, use two. Start Prolog on the first, get the PID and attach strace from the other (most implementations have options such as -p PID). --- Jan P.s. Any other MacOS users suffering from this? _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Markus Triska-2
::
Rate this Message:
Jan Wielemaker <wielemak@...> writes:
> recall what this is called on MacOS (or even whether it exists as > default component), but typically they go by the name 'strace', 'truss', > 'trace' or something sinmilar. I think it's "ktrace" on OSX. _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
I found a tool called "Instruments". I'm not sure I captured the right
kind of info, but here's what I got: #,,Caller,Function,FD,Path,Bytes 1,0,,pread,3,/Developer/Library/PrivateFrameworks/InstrumentsPlugIn.framework/Resources/libsimshim.dylib,4096 2,0,,pread,3,/Developer/Library/PrivateFrameworks/InstrumentsPlugIn.framework/Resources/libsimshim.dylib,4096 3,0,,pread,3,/opt/local/lib/swipl-5.6.52/lib/i386-darwin9.2.0/libpl.dylib,4096 4,0,,pread,3,/opt/local/lib/libgmp.3.dylib,4096 5,0,,pread,3,/opt/local/lib/libreadline.5.2.dylib,4096 6,0,,pread,3,/opt/local/lib/libncursesw.5.dylib,4096 7,0,,pread,3,/opt/local/lib/libncurses.5.dylib,4096 8,0,,read,3,/opt/local/lib/swipl-5.6.52/bin/i386-darwin9.2.0/swipl,1023 9,0,,read,3,/opt/local/lib/swipl-5.6.52/bin/swipl,4096 10,0,,read,3,/opt/local/lib/swipl-5.6.52/swipl.rc,4096 11,0,,read,4,/opt/local/lib/swipl-5.6.52/xpce/prolog/lib/swi_hooks.pl,4096 12,0,,read,4,/opt/local/lib/swipl-5.6.52/xpce/prolog/lib/swi_hooks.pl,4096 13,0,,read,3,/opt/local/lib/swipl-5.6.52/swipl.rc,4096 14,0,,write,2,,23 15,0,,write,2,,16 16,0,,write,2,,9 17,0,,write,2,,8 18,0,,write,2,,6 19,0,,write,2,,1 20,0,,write,2,,1 21,0,,write,2,,48 22,0,,write,2,,1 23,0,,write,2,,68 24,0,,write,2,,1 25,0,,write,2,,64 26,0,,write,2,,1 27,0,,write,2,,51 28,0,,write,2,,1 29,0,,write,2,,1 30,0,,write,2,,50 31,0,,write,2,,1 32,0,,write,2,,1 33,0,,read,0,,4096 34,0,,write,2,,1 35,0,,write,2,,2 36,0,,write,2,,4 37,0,,write,2,,1 38,0,rl_read_key,read,0,,1 39,0,rl_read_key,read,0,,1 40,0,rl_read_key,read,0,,1 41,0,rl_read_key,read,0,,1 42,0,rl_read_key,read,0,,1 43,0,rl_read_key,read,0,,1 44,0,S__fillbuf,read,5,/Users/lager/Development/Synergy/assets/examples/test.xml,4096 45,0,S__fillbuf,read,5,/Users/lager/Development/Synergy/assets/examples/test.xml,4096 46,0,S__flushbuf,write,2,,2 47,0,S__flushbuf,write,2,,62 48,0,S__flushbuf,write,2,,1 49,0,S__flushbuf,write,2,,2 50,0,S__flushbuf,write,2,,62 51,0,S__flushbuf,write,2,,1 52,0,S__flushbuf,write,2,,2 53,0,S__flushbuf,write,2,,62 54,0,S__flushbuf,write,2,,1 55,0,S__flushbuf,write,2,,2 56,0,S__flushbuf,write,2,,62 57,0,S__flushbuf,write,2,,1 58,0,S__flushbuf,write,2,,2 59,0,S__flushbuf,write,2,,62 60,0,S__flushbuf,write,2,,1 61,0,S__flushbuf,write,2,,2 62,0,S__flushbuf,write,2,,62 63,0,S__flushbuf,write,2,,1 64,0,S__flushbuf,write,2,,2 65,0,S__flushbuf,write,2,,62 66,0,S__flushbuf,write,2,,1 67,0,S__flushbuf,write,2,,2 68,0,S__flushbuf,write,2,,62 69,0,S__flushbuf,write,2,,1 70,0,S__flushbuf,write,2,,2 71,0,S__flushbuf,write,2,,62 72,0,S__flushbuf,write,2,,1 73,0,S__flushbuf,write,2,,2 74,0,S__flushbuf,write,2,,62 75,0,S__flushbuf,write,2,,1 76,0,S__flushbuf,write,2,,2 77,0,S__flushbuf,write,2,,62 78,0,S__flushbuf,write,2,,1 79,0,S__flushbuf,write,2,,2 80,0,S__flushbuf,write,2,,62 81,0,S__flushbuf,write,2,,1 82,0,S__flushbuf,write,2,,2 83,0,S__flushbuf,write,2,,62 84,0,S__flushbuf,write,2,,1 85,0,S__flushbuf,write,2,,2 86,0,S__flushbuf,write,2,,62 87,0,S__flushbuf,write,2,,1 88,0,S__flushbuf,write,2,,2 89,0,S__flushbuf,write,2,,62 90,0,S__flushbuf,write,2,,1 91,0,S__flushbuf,write,2,,2 92,0,S__flushbuf,write,2,,62 93,0,S__flushbuf,write,2,,1 94,0,S__flushbuf,write,2,,2 95,0,S__flushbuf,write,2,,62 96,0,S__flushbuf,write,2,,1 97,0,S__flushbuf,write,2,,5 98,0,S__flushbuf,write,2,,1 99,0,S__flushbuf,write,2,,1 100,0,rl_read_key,read,0,,1 Is that what you need? - Torbjörn On Tue, May 20, 2008 at 4:49 PM, Jan Wielemaker <wielemak@...> wrote: > On Tuesday 20 May 2008 16:31, Torbjörn Lager wrote: >> Here's what happens: >> :- use_module(library(http/http_open)). >> :- use_module(library(sgml)). >> >> t(Data) :- >> http_open('http://localhost:5001/pages/assets/examples/test.xml', >> In, []), >> read_data(In), >> close(In). >> >> read_data(In) :- >> repeat, >> time(get_byte(In, B0)), >> B0 == -1, !. >> >> ?- time(t(_)). >> % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) > <snip> >> % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) >> % 1 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) >> % 2,080 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) >> true. > > Ok. So, somehow detecting end-of-file takes very long!? Typically, it is > now time to run a system call tracer to see what happens when. I don't > recall what this is called on MacOS (or even whether it exists as > default component), but typically they go by the name 'strace', 'truss', > 'trace' or something sinmilar. Now run "% strace swipl <options>" and > your program. I think there is by default no timing information > displayed, but you should notice a call blocking 5 seconds. Can you find > that call? If its gets too confusing on your terminal, use two. Start > Prolog on the first, get the PID and attach strace from the other (most > implementations have options such as -p PID). > > --- Jan > > P.s. Any other MacOS users suffering from this? > > _______________________________________________ > SWI-Prolog mailing list > SWI-Prolog@... > https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog > SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
There is something called dtrace. Let me know if you want me to give
that a shot. dhcp-22:~ lager$ dtrace -? Usage: dtrace [-aACeFHlqSvVwZ] [-arch i386|x86_64|ppc|ppc64] [-b bufsz] [-c cmd] [-D name[=def]] [-I path] [-L path] [-o output] [-p pid] [-s script] [-U name] [-x opt[=val]] [-P provider [[ predicate ] action ]] [-m [ provider: ] module [[ predicate ] action ]] [-f [[ provider: ] module: ] func [[ predicate ] action ]] [-n [[[ provider: ] module: ] func: ] name [[ predicate ] action ]] [-i probe-id [[ predicate ] action ]] [ args ... ] predicate -> '/' D-expression '/' action -> '{' D-statements '}' -arch Generate programs and Mach-O files for the specified architecture -a claim anonymous tracing state -A generate plist(5) entries for anonymous tracing -b set trace buffer size -c run specified command and exit upon its completion -C run cpp(1) preprocessor on script files -D define symbol when invoking preprocessor -e exit after compiling request but prior to enabling probes -f enable or list probes matching the specified function name -F coalesce trace output by function -h generate a header file with definitions for static probes -H print included files when invoking preprocessor -i enable or list probes matching the specified probe id -I add include directory to preprocessor search path -l list probes matching specified criteria -L add library directory to library search path -m enable or list probes matching the specified module name -n enable or list probes matching the specified probe name -o set output file -p grab specified process-ID and cache its symbol tables -P enable or list probes matching the specified provider name -q set quiet mode (only output explicitly traced data) -s enable or list probes according to the specified D script -S print D compiler intermediate code -U undefine symbol when invoking preprocessor -v set verbose mode (report stability attributes, arguments) -V report DTrace API version -w permit destructive actions -x enable or modify compiler and tracing options -Z permit probe descriptions that match zero probes On Tue, May 20, 2008 at 5:25 PM, Torbjörn Lager <torbjorn.lager@...> wrote: > I found a tool called "Instruments". I'm not sure I captured the right > kind of info, but here's what I got: > > #,,Caller,Function,FD,Path,Bytes > 1,0,,pread,3,/Developer/Library/PrivateFrameworks/InstrumentsPlugIn.framework/Resources/libsimshim.dylib,4096 > 2,0,,pread,3,/Developer/Library/PrivateFrameworks/InstrumentsPlugIn.framework/Resources/libsimshim.dylib,4096 > 3,0,,pread,3,/opt/local/lib/swipl-5.6.52/lib/i386-darwin9.2.0/libpl.dylib,4096 > 4,0,,pread,3,/opt/local/lib/libgmp.3.dylib,4096 > 5,0,,pread,3,/opt/local/lib/libreadline.5.2.dylib,4096 > 6,0,,pread,3,/opt/local/lib/libncursesw.5.dylib,4096 > 7,0,,pread,3,/opt/local/lib/libncurses.5.dylib,4096 > 8,0,,read,3,/opt/local/lib/swipl-5.6.52/bin/i386-darwin9.2.0/swipl,1023 > 9,0,,read,3,/opt/local/lib/swipl-5.6.52/bin/swipl,4096 > 10,0,,read,3,/opt/local/lib/swipl-5.6.52/swipl.rc,4096 > 11,0,,read,4,/opt/local/lib/swipl-5.6.52/xpce/prolog/lib/swi_hooks.pl,4096 > 12,0,,read,4,/opt/local/lib/swipl-5.6.52/xpce/prolog/lib/swi_hooks.pl,4096 > 13,0,,read,3,/opt/local/lib/swipl-5.6.52/swipl.rc,4096 > 14,0,,write,2,,23 > 15,0,,write,2,,16 > 16,0,,write,2,,9 > 17,0,,write,2,,8 > 18,0,,write,2,,6 > 19,0,,write,2,,1 > 20,0,,write,2,,1 > 21,0,,write,2,,48 > 22,0,,write,2,,1 > 23,0,,write,2,,68 > 24,0,,write,2,,1 > 25,0,,write,2,,64 > 26,0,,write,2,,1 > 27,0,,write,2,,51 > 28,0,,write,2,,1 > 29,0,,write,2,,1 > 30,0,,write,2,,50 > 31,0,,write,2,,1 > 32,0,,write,2,,1 > 33,0,,read,0,,4096 > 34,0,,write,2,,1 > 35,0,,write,2,,2 > 36,0,,write,2,,4 > 37,0,,write,2,,1 > 38,0,rl_read_key,read,0,,1 > 39,0,rl_read_key,read,0,,1 > 40,0,rl_read_key,read,0,,1 > 41,0,rl_read_key,read,0,,1 > 42,0,rl_read_key,read,0,,1 > 43,0,rl_read_key,read,0,,1 > 44,0,S__fillbuf,read,5,/Users/lager/Development/Synergy/assets/examples/test.xml,4096 > 45,0,S__fillbuf,read,5,/Users/lager/Development/Synergy/assets/examples/test.xml,4096 > 46,0,S__flushbuf,write,2,,2 > 47,0,S__flushbuf,write,2,,62 > 48,0,S__flushbuf,write,2,,1 > 49,0,S__flushbuf,write,2,,2 > 50,0,S__flushbuf,write,2,,62 > 51,0,S__flushbuf,write,2,,1 > 52,0,S__flushbuf,write,2,,2 > 53,0,S__flushbuf,write,2,,62 > 54,0,S__flushbuf,write,2,,1 > 55,0,S__flushbuf,write,2,,2 > 56,0,S__flushbuf,write,2,,62 > 57,0,S__flushbuf,write,2,,1 > 58,0,S__flushbuf,write,2,,2 > 59,0,S__flushbuf,write,2,,62 > 60,0,S__flushbuf,write,2,,1 > 61,0,S__flushbuf,write,2,,2 > 62,0,S__flushbuf,write,2,,62 > 63,0,S__flushbuf,write,2,,1 > 64,0,S__flushbuf,write,2,,2 > 65,0,S__flushbuf,write,2,,62 > 66,0,S__flushbuf,write,2,,1 > 67,0,S__flushbuf,write,2,,2 > 68,0,S__flushbuf,write,2,,62 > 69,0,S__flushbuf,write,2,,1 > 70,0,S__flushbuf,write,2,,2 > 71,0,S__flushbuf,write,2,,62 > 72,0,S__flushbuf,write,2,,1 > 73,0,S__flushbuf,write,2,,2 > 74,0,S__flushbuf,write,2,,62 > 75,0,S__flushbuf,write,2,,1 > 76,0,S__flushbuf,write,2,,2 > 77,0,S__flushbuf,write,2,,62 > 78,0,S__flushbuf,write,2,,1 > 79,0,S__flushbuf,write,2,,2 > 80,0,S__flushbuf,write,2,,62 > 81,0,S__flushbuf,write,2,,1 > 82,0,S__flushbuf,write,2,,2 > 83,0,S__flushbuf,write,2,,62 > 84,0,S__flushbuf,write,2,,1 > 85,0,S__flushbuf,write,2,,2 > 86,0,S__flushbuf,write,2,,62 > 87,0,S__flushbuf,write,2,,1 > 88,0,S__flushbuf,write,2,,2 > 89,0,S__flushbuf,write,2,,62 > 90,0,S__flushbuf,write,2,,1 > 91,0,S__flushbuf,write,2,,2 > 92,0,S__flushbuf,write,2,,62 > 93,0,S__flushbuf,write,2,,1 > 94,0,S__flushbuf,write,2,,2 > 95,0,S__flushbuf,write,2,,62 > 96,0,S__flushbuf,write,2,,1 > 97,0,S__flushbuf,write,2,,5 > 98,0,S__flushbuf,write,2,,1 > 99,0,S__flushbuf,write,2,,1 > 100,0,rl_read_key,read,0,,1 > > Is that what you need? > > - Torbjörn > > On Tue, May 20, 2008 at 4:49 PM, Jan Wielemaker <wielemak@...> wrote: >> On Tuesday 20 May 2008 16:31, Torbjörn Lager wrote: >>> Here's what happens: >>> :- use_module(library(http/http_open)). >>> :- use_module(library(sgml)). >>> >>> t(Data) :- >>> http_open('http://localhost:5001/pages/assets/examples/test.xml', >>> In, []), >>> read_data(In), >>> close(In). >>> >>> read_data(In) :- >>> repeat, >>> time(get_byte(In, B0)), >>> B0 == -1, !. >>> >>> ?- time(t(_)). >>> % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) >> <snip> >>> % 1 inferences, 0.00 CPU in 0.00 seconds (0% CPU, Infinite Lips) >>> % 1 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) >>> % 2,080 inferences, 0.00 CPU in 5.00 seconds (0% CPU, Infinite Lips) >>> true. >> >> Ok. So, somehow detecting end-of-file takes very long!? Typically, it is >> now time to run a system call tracer to see what happens when. I don't >> recall what this is called on MacOS (or even whether it exists as >> default component), but typically they go by the name 'strace', 'truss', >> 'trace' or something sinmilar. Now run "% strace swipl <options>" and >> your program. I think there is by default no timing information >> displayed, but you should notice a call blocking 5 seconds. Can you find >> that call? If its gets too confusing on your terminal, use two. Start >> Prolog on the first, get the PID and attach strace from the other (most >> implementations have options such as -p PID). >> >> --- Jan >> >> P.s. Any other MacOS users suffering from this? >> >> _______________________________________________ >> SWI-Prolog mailing list >> SWI-Prolog@... >> https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog >> > SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Jan Wielemaker
::
Rate this Message:
On Tuesday 20 May 2008 17:25, Torbjörn Lager wrote:
> I found a tool called "Instruments". I'm not sure I captured the right > kind of info, but here's what I got: Surely I need your indication of which call is taking so long. Next, I want the system calls and this appears (partly) something else. Markus suggested ktrace. Do you have that? Please delete everything upto a few lines before the problem and indicate clearly which call causes the delay. Cheers --- Jan _______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Torbjörn Lager-2
::
Rate this Message:
I don't have ktrace, but found something called dtrace, documented like so:
dhcp-22:~ lager$ dtrace -? Usage: dtrace [-aACeFHlqSvVwZ] [-arch i386|x86_64|ppc|ppc64] [-b bufsz] [-c cmd] [-D name[=def]] [-I path] [-L path] [-o output] [-p pid] [-s script] [-U name] [-x opt[=val]] [-P provider [[ predicate ] action ]] [-m [ provider: ] module [[ predicate ] action ]] [-f [[ provider: ] module: ] func [[ predicate ] action ]] [-n [[[ provider: ] module: ] func: ] name [[ predicate ] action ]] [-i probe-id [[ predicate ] action ]] [ args ... ] predicate -> '/' D-expression '/' action -> '{' D-statements '}' -arch Generate programs and Mach-O files for the specified architecture -a claim anonymous tracing state -A generate plist(5) entries for anonymous tracing -b set trace buffer size -c run specified command and exit upon its completion -C run cpp(1) preprocessor on script files -D define symbol when invoking preprocessor -e exit after compiling request but prior to enabling probes -f enable or list probes matching the specified function name -F coalesce trace output by function -h generate a header file with definitions for static probes -H print included files when invoking preprocessor -i enable or list probes matching the specified probe id -I add include directory to preprocessor search path -l list probes matching specified criteria -L add library directory to library search path -m enable or list probes matching the specified module name -n enable or list probes matching the specified probe name -o set output file -p grab specified process-ID and cache its symbol tables -P enable or list probes matching the specified provider name -q set quiet mode (only output explicitly traced data) -s enable or list probes according to the specified D script -S print D compiler intermediate code -U undefine symbol when invoking preprocessor -v set verbose mode (report stability attributes, arguments) -V report DTrace API version -w permit destructive actions -x enable or modify compiler and tracing options -Z permit probe descriptions that match zero probes Is this the thing? Could you in that case indicate which flags you want me to run it with, apart from -p ? If dtrace doesn't seem like the right tool, I'll try to find and install ktrace (but likely not until tomorrow). - Torbjörn On Tue, May 20, 2008 at 5:35 PM, Jan Wielemaker <wielemak@...> wrote: > On Tuesday 20 May 2008 17:25, Torbjörn Lager wrote: >> I found a tool called "Instruments". I'm not sure I captured the right >> kind of info, but here's what I got: > > Surely I need your indication of which call is taking so long. Next, I > want the system calls and this appears (partly) something else. Markus > suggested ktrace. Do you have that? Please delete everything upto a few > lines before the problem and indicate clearly which call causes the delay_______________________________________________ SWI-Prolog mailing list SWI-Prolog@... https://mailbox.iai.uni-bonn.de/mailman/listinfo.cgi/swi-prolog |
|
|
Re: Slowness of http_open/3
by Jan Wielemaker
::
Rate this Message:
|
