[racket] Thread creation slow?
90 views
Skip to first unread message
Asumu Takikawa
Aug 10, 2012, 11:51:07 AM8/10/12
to Racket Users
Hi all,
On IRC the other day, this blog article about Racket came up:
http://cxwangyi.wordpress.com/2012/07/29/chinese-whispers-in-racket-and-go/
In it, the author shows a program that creates many threads & channels
and then daisy-chains some communication through them. The Racket
version is significantly slower than the Go version (1 min. vs. 1 sec.).
Is there a performance bug with thread creation here? Alternatively, is
there a different way of coding the example that would make it faster?
Cheers,
Asumu
____________________
Racket Users list:
http://lists.racket-lang.org/users
On IRC the other day, this blog article about Racket came up:
http://cxwangyi.wordpress.com/2012/07/29/chinese-whispers-in-racket-and-go/
In it, the author shows a program that creates many threads & channels
and then daisy-chains some communication through them. The Racket
version is significantly slower than the Go version (1 min. vs. 1 sec.).
Is there a performance bug with thread creation here? Alternatively, is
there a different way of coding the example that would make it faster?
Cheers,
Asumu
____________________
Racket Users list:
http://lists.racket-lang.org/users
Eric Dobson
Aug 10, 2012, 12:11:14 PM8/10/12
to Asumu Takikawa, Racket Users
When I played around with it, I remember that the issue was that
threads created a lot of garbage, and made collecting garbage slow. I
could create about 400 times as many boxes in a chain and get the same
gc time.
This lead to a quadratic(ish) runtime for creating a bunch of threads,
as each later GC took more time.
threads created a lot of garbage, and made collecting garbage slow. I
could create about 400 times as many boxes in a chain and get the same
gc time.
This lead to a quadratic(ish) runtime for creating a bunch of threads,
as each later GC took more time.
Sam Tobin-Hochstadt
Aug 10, 2012, 12:23:44 PM8/10/12
to Eric Dobson, Racket Users
Using my gcstats library, I get the following info. GC is about 75%
of the total runtime, which surprises me since there should be no
garbage until all the channels are set up, which takes most of the
time. Note the extremely large amount of slop space.
305,562,856 bytes allocated in the heap
304,922,088 bytes collected by GC
1,755,839,256 bytes max heap size
975,524,384 bytes max slop
2,722,820,096 bytes peak total memory use
Generation 0: 64 collections, 25,581ms, 25,635.9ms elapsed
Generation 1: 6 collections, 4,980ms, 4,982.54ms elapsed
INIT time 12 ms
MUT time 9,461 ms ( 9,456.13 ms elapsed)
GC time 30,561 ms ( 30,618.52 ms elapsed)
TOTAL time 40,034 ms ( 40,086.65 ms elapsed)
%GC time 76.36% ( 76.40% elapsed)
Alloc rate 32,297,099 bytes per MUT second
for this slightly modified version:
#lang racket/base
(define leftmost (make-channel))
(define (setup-whispers left i n)
(if (>= i n)
left
(let ((right (make-channel)))
(thread (lambda ()
(channel-put left (+ 1 (channel-get right)))))
(setup-whispers right (+ 1 i) n))))
(define rightmost (setup-whispers leftmost 0 100000))
(thread (lambda () (channel-put rightmost 1)))
(channel-get leftmost)
--
sam th
sa...@ccs.neu.edu
of the total runtime, which surprises me since there should be no
garbage until all the channels are set up, which takes most of the
time. Note the extremely large amount of slop space.
305,562,856 bytes allocated in the heap
304,922,088 bytes collected by GC
1,755,839,256 bytes max heap size
975,524,384 bytes max slop
2,722,820,096 bytes peak total memory use
Generation 0: 64 collections, 25,581ms, 25,635.9ms elapsed
Generation 1: 6 collections, 4,980ms, 4,982.54ms elapsed
INIT time 12 ms
MUT time 9,461 ms ( 9,456.13 ms elapsed)
GC time 30,561 ms ( 30,618.52 ms elapsed)
TOTAL time 40,034 ms ( 40,086.65 ms elapsed)
%GC time 76.36% ( 76.40% elapsed)
Alloc rate 32,297,099 bytes per MUT second
for this slightly modified version:
#lang racket/base
(define leftmost (make-channel))
(define (setup-whispers left i n)
(if (>= i n)
left
(let ((right (make-channel)))
(thread (lambda ()
(channel-put left (+ 1 (channel-get right)))))
(setup-whispers right (+ 1 i) n))))
(define rightmost (setup-whispers leftmost 0 100000))
(thread (lambda () (channel-put rightmost 1)))
(channel-get leftmost)
sam th
sa...@ccs.neu.edu
Matthew Flatt
Aug 10, 2012, 12:30:01 PM8/10/12
to Sam Tobin-Hochstadt, Racket Users
Yes, I see some O(N) behavior for N threads on each GC, and I'm trying
to fix it.
to fix it.
Matthew Flatt
Aug 10, 2012, 3:05:28 PM8/10/12
to Racket Users
I've pushed some improvements in v5.3.0.18.
On my machine (MacBook Air, 32-bit mode):
v5.3: 27.274u 5.868s 0:35.14 94.2% 0+0k 6+2io 622pf+0w
v5.3.0.18: 5.851u 2.494s 0:09.12 91.4% 0+0k 2+0io 691pf+0w
I believe that most of the savings are in corrections to avoid O(N)
setup for N threads for each minor GC.
Racket threads can be made lighter by adjusting the
`current-thread-initial-stack-size' parameter. If I change the program
to use
(parameterize ([current-thread-initial-stack-size 100])
(setup-whispers leftmost 0 100000))
then I get
3.854u 1.175s 0:05.32 94.3% 0+0k 1+1io 689pf+0w
The trade-off for a smaller initial stack size is that deeper recursion
is more expensive.
Here are results in 64-bit mode on my machine:
v5.3: 37.339u 24.869s 1:29.12 69.7% 0+0k 1+0io 49597pf+0w
v5.3.0.18: 8.948u 10.030s 0:36.29 52.2% 0+0k 2+0io 43919pf+0w
v5.3.0.18/100: 6.334u 3.317s 0:10.83 89.0% 0+0k 0+0io 0pf+0w
For the first two, there's a big difference between CPU+user time and
real time. Those configurations apparently use enough memory to
aggravate my machine's memory system.
On my machine (MacBook Air, 32-bit mode):
v5.3: 27.274u 5.868s 0:35.14 94.2% 0+0k 6+2io 622pf+0w
v5.3.0.18: 5.851u 2.494s 0:09.12 91.4% 0+0k 2+0io 691pf+0w
I believe that most of the savings are in corrections to avoid O(N)
setup for N threads for each minor GC.
Racket threads can be made lighter by adjusting the
`current-thread-initial-stack-size' parameter. If I change the program
to use
(parameterize ([current-thread-initial-stack-size 100])
(setup-whispers leftmost 0 100000))
then I get
3.854u 1.175s 0:05.32 94.3% 0+0k 1+1io 689pf+0w
The trade-off for a smaller initial stack size is that deeper recursion
is more expensive.
Here are results in 64-bit mode on my machine:
v5.3: 37.339u 24.869s 1:29.12 69.7% 0+0k 1+0io 49597pf+0w
v5.3.0.18: 8.948u 10.030s 0:36.29 52.2% 0+0k 2+0io 43919pf+0w
v5.3.0.18/100: 6.334u 3.317s 0:10.83 89.0% 0+0k 0+0io 0pf+0w
For the first two, there's a big difference between CPU+user time and
real time. Those configurations apparently use enough memory to
aggravate my machine's memory system.
Robby Findler
Aug 10, 2012, 3:14:08 PM8/10/12
to Matthew Flatt, Racket Users
That gets us to within a factor of 2 or 3 of the go version, I guess?
Robby
Robby
Marijn
Aug 13, 2012, 5:45:49 AM8/13/12
to Robby Findler, Matthew Flatt, Racket Users
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
On 10-08-12 21:14, Robby Findler wrote:
> That gets us to within a factor of 2 or 3 of the go version, I
> guess?
If the 1 minute versus 1 second is accurate, then there was a 60x
performance difference in the beginning and Matthew managed to improve
it by a factor of 5 or even slightly over 6 when tuning, so it seems
to me Racket would still be slower by 10x.
Marijn
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.19 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEYEARECAAYFAlAozM0ACgkQp/VmCx0OL2z3JACfTvfn6BV9DQNKpxho6JenDobo
N7YAn2GhhDTBB31wM12Naw+Jrl1nV+rs
=wbzg
-----END PGP SIGNATURE-----
Hash: SHA1
On 10-08-12 21:14, Robby Findler wrote:
> That gets us to within a factor of 2 or 3 of the go version, I
> guess?
performance difference in the beginning and Matthew managed to improve
it by a factor of 5 or even slightly over 6 when tuning, so it seems
to me Racket would still be slower by 10x.
Marijn
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.19 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEYEARECAAYFAlAozM0ACgkQp/VmCx0OL2z3JACfTvfn6BV9DQNKpxho6JenDobo
N7YAn2GhhDTBB31wM12Naw+Jrl1nV+rs
=wbzg
-----END PGP SIGNATURE-----
Danny Yoo
Aug 18, 2012, 10:40:19 PM8/18/12
to Marijn, Matthew Flatt, Racket Users, Robby Findler
If the 1 minute versus 1 second is accurate, then there was a 60x
performance difference in the beginning and Matthew managed to improve
it by a factor of 5 or even slightly over 6 when tuning, so it seems
to me Racket would still be slower by 10x.
I checked with the blog author a few days ago, and he reports that one of his test programs runs significantly slower under the development version of Racket vs. 5.2.1, after these changes:
Thanks for the update, and I am now looking forward to v5.3.0.18.
One more thing: I just compared v5.2.1 with v5.3.0.17, and found the latter runs times slower.
$time racket-5.2.1/bin/racket /tmp/a.rkt
real 0m35.430s
user 0m26.235s
sys 0m5.334s
$time ~/racket-5.3.0.17/bin/racket /tmp/a.rkt
real 1m54.070s
user 0m47.368s
sys 0m27.836s
Reference: the comments section of http://cxwangyi.wordpress.com/2012/07/29/chinese-whispers-in-racket-and-go/
Maybe someone can follow up with the author directly?
Matthew Flatt
Aug 19, 2012, 10:26:02 AM8/19/12
to Danny Yoo, Racket Users
At Sat, 18 Aug 2012 22:40:19 -0400, Danny Yoo wrote:
> > If the 1 minute versus 1 second is accurate, then there was a 60x
> > performance difference in the beginning and Matthew managed to improve
> > it by a factor of 5 or even slightly over 6 when tuning, so it seems
> > to me Racket would still be slower by 10x.
>
>
> I checked with the blog author a few days ago, and he reports that one of
> his test programs runs significantly slower under the development version
> of Racket vs. 5.2.1, after these changes:
>
> am<http://cxwangyi.wordpress.com/2012/07/29/chinese-whispers-in-racket-and-go/#c
> > If the 1 minute versus 1 second is accurate, then there was a 60x
> > performance difference in the beginning and Matthew managed to improve
> > it by a factor of 5 or even slightly over 6 when tuning, so it seems
> > to me Racket would still be slower by 10x.
>
>
> I checked with the blog author a few days ago, and he reports that one of
> his test programs runs significantly slower under the development version
> of Racket vs. 5.2.1, after these changes:
>
> omment-478>
>
> Thanks for the update, and I am now looking forward to v5.3.0.18.
>
> One more thing: I just compared v5.2.1 with v5.3.0.17, and found the latter
> runs times slower.
Version 5.3.0.17 is before the repair. Still, the results for v5.2.1
> Thanks for the update, and I am now looking forward to v5.3.0.18.
>
> One more thing: I just compared v5.2.1 with v5.3.0.17, and found the latter
> runs times slower.
and v5.3.0.17 should have been the same, so I've followed up there to
ask for more information.
liweijian
Dec 21, 2019, 7:38:36 AM12/21/19
to Racket Users
Some updates with Racket v7.5[cs] and go 1.13.5 in my Mac mini 2018:
$ raco exe whispers.rkt
$ time ./whispers
#<thread:...racket/whispers.rkt:15:8>
100001
1.85 real 1.63 user 0.20 sys
$ time ./hello
100001
0.28 real 0.54 user 0.14 sys
Seems that Racket v7.5[cs] doing much better right now compare with the original post : https://cxwangyi.wordpress.com/2012/07/29/chinese-whispers-in-racket-and-go/
wangyi@WangYiIMac$time go run daisy-chain.go
100001
real 0m1.045s
user 0m0.367s
sys 0m0.231s
wangyi@WangYiIMac$raco exe daisy-chain.rkt && time ./daisy-chain
100001
real 0m42.905s
user 0m29.579s
sys 0m11.075s
在 2012年8月19日星期日 UTC+8下午10:26:02，Matthew Flatt写道：
Reply all
Reply to author
Forward
0 new messages