| Author |
Message |
< Erlang ~ Strange behavior of gen_server logging messages |
| odi |
 Posted: Fri Feb 18, 2011 12:19 pm |
 |
|
|
Joined: 19 Feb 2009
Posts: 9
|
I have a sample application where a lot of processes send synchronous messages to gen_server which logs it using file module. With 2000 processes, each sending 100 messages of 50 bytes it takes about 15 seconds.
[A]
Client1 ---\
Client2 ---- Server1 --- IO
Client3 ---/
However I noticed something what seemed strange at first - if each message was sent through additional gen_server with call/2 function then logging took only 5 seconds.
[B]
Client1 ---\
Client2 ---- Server1 --- Server2 --- IO
Client3 ---/
My idea was that in [A] messages from clients were accumulating in the Server1 process queue and when message was to be logged by IO then io_reply would go to the end of the queue. I corrected receive statement used in io:execute_request/2 according to OTP-8623 (see my_file:execute_request/2). With this enhancement processing of all messages with 1 gen_server took only 7.5 seconds instead of 15.
Attached files - my_server.erl, my_client.erl, my_file.erl
Usage:
my_server:start_link(dir_proc).
my_server:start_link(redir_proc).
% starts 2000 processes each logging 100 messages of 50 bytes
my_client:start(2000,100,50,{direct, dir_proc, my_file}). % solution A with corrected IO
my_client:start(2000,100,50,{redirect, redir_proc, dir_proc, file}). % solution B with standard IO
I used Erlang R14B.
My question is why the solution with 2 gen_servers (5s) is still faster than the solution with only 1 gen_server (7.5s)? |
|
|
| Back to top |
 
|
| odi |
| Posted: Mon Feb 21, 2011 1:10 pm |
|
|
|
Joined: 19 Feb 2009
Posts: 9
|
After running this program with eprof it turned out that erlang:demonitor/1 is a most expensive function.
In my_file:execute_request/2 function
Code: receive
{io_reply, Mref, Reply} ->
erlang:demonitor(Mref),
receive
{'DOWN', Mref, _, _, _} -> true
after 0 -> true
end,
Reply;
it appears that the receive statement after receiving io_reply and demonitoring a process reference is inefficient. According to http://www.erlang.org/doc/man/erlang.html#demonitor-2 it was changed to Code: erlang:demonitor(Mref, [flush])
Now my version of a program with only 1 gen_server takes only 3.5 seconds. |
|
|
| Back to top |
|
| rvirding |
| Posted: Tue Feb 22, 2011 9:19 am |
|
|
|
User
Joined: 30 Aug 2006
Posts: 452
Location: Stockholm, Sweden
|
One reason why the solution with 2 gen_servers is faster could be because of the number of messages in the message queue of the process doing the io request. In the 1 gen_server version there will be 2000 requests in message queue, one from each client as even if the processing is synchronous each client will have sent off a request. In the 2 gen_server version there will only be one request in the queue. As the message queue is scanned for 'DOWN' and 'EXIT' messages for each io request this will take longer time when the input queue is longer. This scanning will also take place in your second improved version even if it is done implicitly by erlang:demonitor/2.
This is a case where knowing how the message queue is processed can help you.
As you know you are writing to a file you might try opening the file in 'raw' mode and using file:write/2 instead. This should be faster but is less versatile. |
_________________
Robert Virding, Erlang Solutions Ltd. |
|
| Back to top |
 
|
| odi |
| Posted: Thu Feb 24, 2011 2:38 pm |
|
|
|
Joined: 19 Feb 2009
Posts: 9
|
Thanks for your reply Robert,
You're right when you say that in the solution [B] there'll be only 1 request in 2nd gen_server's queue but there'll be almost 2000 requests in a 1st gen_server's queue and it has to scan for 'DOWN' and 'EXIT' messages too. Main problem in solution [A] was an inefficient io_reply receive statement.
I also checked the 'raw' mode as you suggested - it is faster in a 2 gen_server version yet still noticably slower in a 1 gen_server solution. I looked at a code of prim_file which is used underneath and it probably has the same problem; inefficient receive statement used to get response from a file driver. |
|
|
| Back to top |
|
| rvirding |
| Posted: Fri Feb 25, 2011 4:18 pm |
|
|
|
User
Joined: 30 Aug 2006
Posts: 452
Location: Stockholm, Sweden
|
odi wrote: You're right when you say that in the solution there'll be only 1 request in 2nd gen_server's queue but there'll be almost 2000 requests in a 1st gen_server's queue and it has to scan for 'DOWN' and 'EXIT' messages too. Main problem in solution [A] was an inefficient io_reply receive statement.
No! Well yes, there will be almost 2000 requests on in the 1st server's queue BUT this doesn't matter in case. It is the io_reply which does the check for 'DOWN' and 'EXIT' and so it is ONLY in the server which writes to the file where the input queue length matters. The other requests don't result in that type of check, they just take the next request, do it and send back a reply, so the input queue length is unimportant.
So in case [A] it is the server which is writing to the file and does the checks on the input queue. In case [\B] while the 1st server does have a long input queue it does not check it and only sends one message at a time to the 2nd server (gen:call/2 is synchronous) so the input queue of the 2nd server will be short and the io_reply will have very short queue in which to scan for 'DOWN' and 'EXIT' (one message).
So in the second case you will have a long input queue where the length doesn't matter and a short one where it does matter. That is why it is faster.
This way of scanning the input queue is necessary for io_reply to ensure that the process which handles the actual io-requests is alive and to check if it dies before it returns a reply. Otherwise the calling process could hang. |
_________________
Robert Virding, Erlang Solutions Ltd. |
|
| Back to top |
|
| odi |
| Posted: Fri Mar 04, 2011 7:42 am |
|
|
|
Joined: 19 Feb 2009
Posts: 9
|
Maybe I'm misunderstanding something but in gen_server's call there is also a check for 'DOWN' and 'EXIT' messages after reply is received (it's done through erlang:demonitor/2 - see gen_server:do_call/4).
According to you:
rvirding wrote: As the message queue is scanned for 'DOWN' and 'EXIT' messages for each io request this will take longer time when the input queue is longer. This scanning will also take place in your second improved version even if it is done implicitly by erlang:demonitor/2.
In both cases if there's a long input queue in a gen_server process the queue length does matter however it was corrected with OTP-8623 enhancement. |
|
|
| Back to top |
|
| dongdongwu |
| Posted: Thu Sep 20, 2012 6:08 am |
|
|
|
User
Joined: 19 Sep 2012
Posts: 236
|
His good friend Diane said: "Christian Louboutin Men Shoes was a magician, he make shoes is immediately put his female people with legs and advantage. He understands women wanted to do and can make them into beautiful Cinderella." Madonna often in its concert wearing Christian louboutin high heels , and some famous superstar like Angelina jolie, mariah Carey, beyonce Knowles, the famous Japanese singer YaYouMei Hamasaki helps Christian Louboutin Men Shoes set up its powerful position. The youngest customers will count Tom cruise's daughter sully cruz. Louboutin made for only a pair of handmade Christian Louboutin high heel Shoes! Want to be more fashion? Put on Christian Louboutin Outlet !
Candy colors of the chalaza high-heeled shoes with lolita type allure, set full finely gem blue "neon shoes" is to need to use "sexy" to describe. Each pair are worth careful appreciation of lithe and graceful fairy ludaoli, what kind of most let you move?Christian Louboutin Men Shoes that one brush red is always cannot resist the temptation, Christian Louboutin men outlet continue to use the days of high 8cm above slender heel proclaim the sexy and luxuriant. The bowknot on black pointed high-heeled shoes with sharp rivet concomitant, wild python met enchanting color printing grain, It is that pairs of high-heeled shoes lets Carrie more feminine flavour. Like Christian Louboutin for men her word. |
|
|
| Back to top |
|
|
|
Digg It
Del.icio.us
Reddit
Facebook
Stumble Upon
Technorati
