Hi all
Me again with the profiler filter. I started implementing the
per-connection storage for profiler data, and bumped into weird issue when
returning the request server simply dies. Second cut of profiler filter
(WIP) is at: http://pastebin.com/2GPwPFjx
If anyone is kind enough to look at, put the code into
tools/filters/profiler.c, add profiler.so to Makefile in same directory,
and add the following to your config:
== begin config changes ==
profiler = Filter(
name="/usr/local/lib/mongrel2/filters/profiler.so",
settings ={}
)
# --snip--
main = Server(
...
filters = [profiler]
...
)
servers = [main]
== end config changes ==
Now depending on the port - start it with sudo or without. The server
loads with the filter.
Now do a request on a simple file (not sure if states covered work for
handler/proxy) on that server. Here's the output that I get:
== begin debug output ==
DEBUG src/state.rl:53: --> parse(OPEN:107) State_exec:53
DEBUG profiler.c:21: Begin: Resource temporarily unavailable
DEBUG profiler.c:23: Alloc: Resource temporarily unavailable
DEBUG profiler.c:27: Get: Resource temporarily unavailable
DEBUG profiler.c:42: Received request. Getting current time.
DEBUG src/state.rl:54: --> register_request(REQ_RECV:110) State_exec:54
DEBUG src/connection.c:558: HTTP MESSAGE
DEBUG src/state.rl:57: --> route_request(HTTP_REQ:105) State_exec:57
DEBUG src/server.c:359: Looking for target host: localhost
DEBUG src/routing.c:220: Found simple suffix: localhost for target: localhost
DEBUG src/host.c:140: MATCHING BACKEND IN HOST 0x7fe261e1acb0 AGAINST / in
ROUTES: 0x7fe261e1ad30
DEBUG src/routing.c:235: Searching for route: / in map: 0x7fe261e1ad30
DEBUG src/routing.c:240: Found simple prefix: /
DEBUG src/host.c:145: Found backend at /
DEBUG src/state.rl:63: --> http_to_directory(DIRECTORY:102) State_exec:63
DEBUG src/dir.c:275: Lazy normalized base path localhost/ into
/Users/eimantas/Sites/localhost
DEBUG src/dir.c:343: Building target from base:
/Users/eimantas/Sites/localhost prefix: / path: / index_file: index.html
DEBUG src/dir.c:434: TESTING WITH: if_match: (null), if_none_match:
(null), if_unmodified_since: 0, if_modified_since: 0
DEBUG profiler.c:21: Begin: Resource temporarily unavailable
DEBUG profiler.c:23: Alloc: Resource temporarily unavailable
DEBUG profiler.c:27: Get: Resource temporarily unavailable
DEBUG profiler.c:47: Sending response. Getting the diff.
DEBUG profiler.c:50: Dereferencing start time value
== end debug output ==
After that the server just dies. When running WITHOUT sudo - the return
code of last command is 0. The gettimeofday may fill the errno var with
EFAULT (invalid memory) or EPERM (not run by root), but as you see from
the output, even when running server not in daemon mode - it doesn't do
that, nor it provides any other information on why the server died.
Can anyone help me dissect this thing?
All the best,
Eimantas Vaiciunas
P.S. My server config can be found at http://pastebin.com/FLQ6QdSH
On 26/12/11 20:08, Eimantas Vaiciunas wrote:
Not to sound harsh, but try to get the filter working right before
complaining about crashes.
1. You're adding the item to the hash, but never fetching it back;
your comparison function always returns 0.
2. You're adding an item with one hash, but looking for another: you
hash the connection's value, which changes with every pass through
the filter (there is no data when the request comes, but there is
when the response comes).
3. Your math is all wrong.
While using your version I get segfaults, probably caused because
you're fetching garbage from the hash table.
These two functions fix your first two issues.
hash_val_t profsess_hash(const void *data)
{
// The pointer to the connection is unique enough, but it may
not be "hashy" enough, so this could be improved.
return (hash_val_t)data;
}
hash_comp_t profsess_cmp(const void *ps0, const void *ps1)
{
return memcmp(ps0, ps1, sizeof(hash_val_t));
}
The last one is fixed with
long int startTimeInt = startTime->tv_sec * 1000 +
startTime->tv_usec / 1000;
long int endTimeInt = currentTime->tv_sec * 1000 +
currentTime->tv_usec / 1000;
With these changes, I get the correct responses:
DEBUG profiler.c:22: Begin: Success
DEBUG profiler.c:24: Alloc: Success
DEBUG profiler.c:28: Get: Success
DEBUG profiler.c:45: Received request. Getting current time.
DEBUG profiler.c:22: Begin: Success
DEBUG profiler.c:24: Alloc: Success
DEBUG profiler.c:28: Get: Success
DEBUG profiler.c:50: Sending response. Getting the diff.
DEBUG profiler.c:53: Dereferencing start time value
DEBUG profiler.c:57: Request took 0ms
Also, setting errno to 0 at the start of the function avoids getting
fake error messages (then again, you probably shouldn't be printing
strerror unless there's an actual error).
--
Guillermo O. «Tordek» Freschi. Programador, Escritor, Genio Maligno.
http://tordek.com.ar :: http://twitter.com/tordek
Thanks for your elaborate answer. I'll be sure to double check everything before crafting emails like this. On to the development then! All the best, Eimantas Vaiciunas --- Eimantas Vaiciunas iOS Developer, Mobile dept. Skype: eimantas.vaiciunas Cell: +350 5403 1260 On Dec 27, 2011, at 2:35 AM, Tordek wrote: > On 26/12/11 20:08, Eimantas Vaiciunas wrote: > > Not to sound harsh, but try to get the filter working right before > complaining about crashes. > > 1. You're adding the item to the hash, but never fetching it back; > your comparison function always returns 0. > 2. You're adding an item with one hash, but looking for another: you > hash the connection's value, which changes with every pass through > the filter (there is no data when the request comes, but there is > when the response comes). > 3. Your math is all wrong. > > While using your version I get segfaults, probably caused because > you're fetching garbage from the hash table. > > These two functions fix your first two issues. > > hash_val_t profsess_hash(const void *data) > { > // The pointer to the connection is unique enough, but it may > not be "hashy" enough, so this could be improved. > > return (hash_val_t)data; > } > > > hash_comp_t profsess_cmp(const void *ps0, const void *ps1) > { > return memcmp(ps0, ps1, sizeof(hash_val_t)); > } > > The last one is fixed with > > long int startTimeInt = startTime->tv_sec * 1000 + > startTime->tv_usec / 1000; > long int endTimeInt = currentTime->tv_sec * 1000 + > currentTime->tv_usec / 1000; > > With these changes, I get the correct responses: > > DEBUG profiler.c:22: Begin: Success > DEBUG profiler.c:24: Alloc: Success > DEBUG profiler.c:28: Get: Success > DEBUG profiler.c:45: Received request. Getting current time. > DEBUG profiler.c:22: Begin: Success > DEBUG profiler.c:24: Alloc: Success > DEBUG profiler.c:28: Get: Success > DEBUG profiler.c:50: Sending response. Getting the diff. > DEBUG profiler.c:53: Dereferencing start time value > DEBUG profiler.c:57: Request took 0ms > > Also, setting errno to 0 at the start of the function avoids getting > fake error messages (then again, you probably shouldn't be printing > strerror unless there's an actual error). > > -- > Guillermo O. «Tordek» Freschi. Programador, Escritor, Genio Maligno. > http://tordek.com.ar :: http://twitter.com/tordek All the best, Eimantas Vaiciunas
Just to add, you can check out the whole thing from my fork of mongrel2 at github: https://github.com/eimantas/mongrel2/tree/feature/profiler-filter All the best, Eimantas Vaiciunas On Dec 27, 2011, at 1:08 AM, Eimantas Vaiciunas wrote: > Hi all > > Me again with the profiler filter. I started implementing the per-connection storage for profiler data, and bumped into weird issue when returning the request server simply dies. Second cut of profiler filter (WIP) is at: http://pastebin.com/2GPwPFjx > > If anyone is kind enough to look at, put the code into tools/filters/profiler.c, add profiler.so to Makefile in same directory, and add the following to your config: > == begin config changes == > profiler = Filter( > name="/usr/local/lib/mongrel2/filters/profiler.so", > settings ={} > ) > # --snip-- > main = Server( > ... > filters = [profiler] > ... > ) > > servers = [main] > == end config changes == > > Now depending on the port - start it with sudo or without. The server loads with the filter. > > Now do a request on a simple file (not sure if states covered work for handler/proxy) on that server. Here's the output that I get: > > == begin debug output == > DEBUG src/state.rl:53: --> parse(OPEN:107) State_exec:53 > DEBUG profiler.c:21: Begin: Resource temporarily unavailable > DEBUG profiler.c:23: Alloc: Resource temporarily unavailable > DEBUG profiler.c:27: Get: Resource temporarily unavailable > DEBUG profiler.c:42: Received request. Getting current time. > DEBUG src/state.rl:54: --> register_request(REQ_RECV:110) State_exec:54 > DEBUG src/connection.c:558: HTTP MESSAGE > DEBUG src/state.rl:57: --> route_request(HTTP_REQ:105) State_exec:57 > DEBUG src/server.c:359: Looking for target host: localhost > DEBUG src/routing.c:220: Found simple suffix: localhost for target: localhost > DEBUG src/host.c:140: MATCHING BACKEND IN HOST 0x7fe261e1acb0 AGAINST / in ROUTES: 0x7fe261e1ad30 > DEBUG src/routing.c:235: Searching for route: / in map: 0x7fe261e1ad30 > DEBUG src/routing.c:240: Found simple prefix: / > DEBUG src/host.c:145: Found backend at / > DEBUG src/state.rl:63: --> http_to_directory(DIRECTORY:102) State_exec:63 > DEBUG src/dir.c:275: Lazy normalized base path localhost/ into /Users/eimantas/Sites/localhost > DEBUG src/dir.c:343: Building target from base: /Users/eimantas/Sites/localhost prefix: / path: / index_file: index.html > DEBUG src/dir.c:434: TESTING WITH: if_match: (null), if_none_match: (null), if_unmodified_since: 0, if_modified_since: 0 > DEBUG profiler.c:21: Begin: Resource temporarily unavailable > DEBUG profiler.c:23: Alloc: Resource temporarily unavailable > DEBUG profiler.c:27: Get: Resource temporarily unavailable > DEBUG profiler.c:47: Sending response. Getting the diff. > DEBUG profiler.c:50: Dereferencing start time value > == end debug output == > > After that the server just dies. When running WITHOUT sudo - the return code of last command is 0. The gettimeofday may fill the errno var with EFAULT (invalid memory) or EPERM (not run by root), but as you see from the output, even when running server not in daemon mode - it doesn't do that, nor it provides any other information on why the server died. > > Can anyone help me dissect this thing? > > All the best, > Eimantas Vaiciunas > > P.S. My server config can be found at http://pastebin.com/FLQ6QdSH