Environment:
- Ubuntu 12.04 Desktop & Server
- PHP 5.3.10
- Gearman (libgearman 1.1.5 with PHP Extension 1.1.1)
- Multiple servers on LAN
I've been working on distributed processes for some time. Most of these tools require DB access. Eventually this led to server/resource issues due to MySQL getting overwhelmed (as far as I can tell).
I've tried a number of solutions and now I'm trying Gearman. I have queries being sent to workers and I'm getting the correct response back to the client. (I haven't yet tested out returning errors.)
My problem is that my test code has 3 sql statements - all selects. Probably 4 times out of 5 when I run this test script 2 or the queries take 3 sec to return and 1 takes less 0.01 sec to complete. On the 5th attempt with this script all 3 queries take 3 sec. The query that takes less than 0.01 sec is often times the last query but not always. And I have a direct DB connection executing the same queries and they all return in the 0.002 sec range.
This behavior doesn't appear to change whether I run 1 or up to 4 workers. The client is using doHigh.
Specifically here are some times (in seconds or Unix Epoch time) from my latest test run:
- Execution Time of Worker: 0.00066
- Client Job Request Time: 1380128735.505
- Worker Job Received Time: 1380128744.3248
- Client Receive Result Time: 1380128744.3262
Obviously this request took about 9 seconds not 3. The client and worker both reside on the same machine. The job server is open to the LAN so it is listening on 192.168.1.XX instead of 127.0.0.1. Sending the job to a job server on a different machine (faster, more RAM, almost no load) the times are effectively the same.
Is this the expected behavior of Gearman?
Thanks
Per suggestions on another forum I logged what was happening using --verbose=DEBUG. Long story short the gaps in time appear to be happening btwn Sent NOOP to 192.168.1... and 192.168.1... Ready POLLIN -> ... Here is a relevant log excerpt (wish I knew how to format it better):
INFO 2013-09-26 02:39:43.873141 [ main ] Accepted connection from 192.168.1.70:39280 DEBUG 2013-09-26 02:39:43.873200 [ 3 ] Received CON wakeup event -> libgearman-server/gearmand_thread.cc:602 DEBUG 2013-09-26 02:39:43.873244 [ 3 ] setsockopt() 33 -> libgearman-server/io.cc:809 DEBUG 2013-09-26 02:39:43.873276 [ 3 ] 192.168.1.70:39280 Watching POLLIN -> libgearman-server/gearmand_thread.cc:151 INFO 2013-09-26 02:39:43.873292 [ 3 ] Gear connection made DEBUG 2013-09-26 02:39:43.873309 [ 3 ] 192.168.1.70:39280 Ready POLLIN -> libgearman-server/gearmand_con.cc:118 DEBUG 2013-09-26 02:39:43.873333 [ 3 ] read 22 bytes -> libgearman-server/io.cc:686 INFO 2013-09-26 02:39:43.873346 [ 3 ] Gear unpack DEBUG 2013-09-26 02:39:43.873363 [ 3 ] GEAR length: 0 gearmand_command_t: GEARMAN_COMMAND_OPTION_REQ -> libgearman-server/plugins/protocol/gear/protocol.cc:248 DEBUG 2013-09-26 02:39:43.873375 [ 3 ] Received OPTION_REQ 192.168.1.70:3093758901 -> libgearman-server/thread.cc:318 DEBUG 2013-09-26 02:39:43.873399 [ 3 ] 192.168.1.70:39280 Watching POLLIN -> libgearman-server/gearmand_thread.cc:151 DEBUG 2013-09-26 02:39:43.873411 [ proc ] 192.168.1.70:39280 packet command OPTION_REQ -> libgearman-server/server.cc:98 DEBUG 2013-09-26 02:39:43.873457 [ proc ] 'exceptions' -> libgearman-server/server.cc:485 DEBUG 2013-09-26 02:39:43.873492 [
3 ] Received RUN wakeup event -> libgearman-server/gearmand_thread.cc:607 DEBUG 2013-09-26 02:39:43.873508 [ 3 ] GEAR length: 0 gearmand_command_t: GEARMAN_COMMAND_OPTION_RES -> libgearman-server/plugins/protocol/gear/protocol.cc:274 DEBUG 2013-09-26 02:39:43.873551 [ 3 ] send() 22 bytes to peer 192.168.1.70:39280 -> libgearman-server/io.cc:275 DEBUG 2013-09-26 02:39:43.873565 [ 3 ] Sent OPTION_RES to 192.168.1.70:-1201208395 -> libgearman-server/thread.cc:365 DEBUG 2013-09-26 02:39:43.873583 [ 3 ] 192.168.1.70:39280 Ready POLLIN -> libgearman-server/gearmand_con.cc:118 DEBUG 2013-09-26 02:39:43.873599 [ 3 ] read 177 bytes -> libgearman-server/io.cc:686 INFO 2013-09-26 02:39:43.873610 [ 3 ] Gear unpack DEBUG 2013-09-26 02:39:43.873635 [ 3 ] GEAR length: 118 gearmand_command_t: GEARMAN_COMMAND_SUBMIT_JOB_HIGH -> libgearman-server/plugins/protocol/gear/protocol.cc:248 DEBUG 2013-09-26 02:39:43.873648 [ 3 ] Received SUBMIT_JOB_HIGH 192.168.1.70:3093758901 -> libgearman-server/thread.cc:318 DEBUG 2013-09-26 02:39:43.873668 [ 3 ] 192.168.1.70:39280 Watching POLLIN -> libgearman-server/gearmand_thread.cc:151 DEBUG 2013-09-26 02:39:43.873675 [ proc ] 192.168.1.70:39280 packet command SUBMIT_JOB_HIGH -> libgearman-server/server.cc:98 DEBUG 2013-09-26 02:39:43.873696 [ proc ] Received submission, function:db_access unique:e692b4c2-2654-11e3-bc34-90e6baa255ea with 2 arguments -> libgearman-server/server.cc:231 DEBUG 2013-09-26 02:39:43.873715 [ proc ] Comparing queue 0 to limit 0 for priority 0 -> libgearman-server/job.cc:174 NOTICE 2013-09-26 02:39:43.873754 [ proc ] accepted,db_access,e692b4c2-2654-11e3-bc34-90e6baa255ea,0 -> libgearman-server/server.cc:301 DEBUG 2013-09-26 02:39:43.873764 [
3 ] Received RUN wakeup event -> libgearman-server/gearmand_thread.cc:607 DEBUG 2013-09-26 02:39:43.873763 [ 4 ] Received RUN wakeup event -> libgearman-server/gearmand_thread.cc:607 DEBUG 2013-09-26 02:39:43.873794 [ 3 ] GEAR length: 0 gearmand_command_t: GEARMAN_COMMAND_JOB_CREATED -> libgearman-server/plugins/protocol/gear/protocol.cc:274 DEBUG 2013-09-26 02:39:43.873803 [ 4 ] GEAR length: 0 gearmand_command_t: GEARMAN_COMMAND_NOOP -> libgearman-server/plugins/protocol/gear/protocol.cc:274 DEBUG 2013-09-26 02:39:43.873824 [ 3 ] send() 25 bytes to peer 192.168.1.70:39280 -> libgearman-server/io.cc:275 DEBUG 2013-09-26 02:39:43.873838 [ 3 ] Sent JOB_CREATED to 192.168.1.70:-1201208395 -> libgearman-server/thread.cc:365 DEBUG 2013-09-26 02:39:43.873850 [ 4 ] send() 12 bytes to peer 192.168.1.70:39219 -> libgearman-server/io.cc:275 DEBUG 2013-09-26 02:39:43.873865 [ 4 ] Sent NOOP to 192.168.1.70:-1201209827 -> libgearman-server/thread.cc:365 DEBUG 2013-09-26 02:39:47.032010 [
4 ] 192.168.1.70:39219 Ready POLLIN -> libgearman-server/gearmand_con.cc:118 DEBUG 2013-09-26 02:39:47.032061 [ 4 ] read 12 bytes -> libgearman-server/io.cc:686 INFO 2013-09-26 02:39:47.032074 [ 4 ] Gear unpack DEBUG 2013-09-26 02:39:47.032086 [ 4 ] GEAR length: 0 gearmand_command_t: GEARMAN_COMMAND_GRAB_JOB_ALL -> libgearman-server/plugins/protocol/gear/protocol.cc:248 DEBUG 2013-09-26 02:39:47.032098 [ 4 ] Received GRAB_JOB_ALL 192.168.1.70:3093757469 -> libgearman-server/thread.cc:318 DEBUG 2013-09-26 02:39:47.032119 [ 4 ] 192.168.1.70:39219 Watching POLLIN -> libgearman-server/gearmand_thread.cc:151 DEBUG 2013-09-26 02:39:47.032134 [ proc ] 192.168.1.70:39219 packet command GRAB_JOB_ALL -> libgearman-server/server.cc:98 DEBUG 2013-09-26 02:39:47.032170 [ proc ] Jobs available for db_access: 1 -> libgearman-server/gearmand_con.cc:291 DEBUG 2013-09-26 02:39:47.032200 [ proc ] Sending reduce submission, Partitioner: db_access(9) Reducer: (0) Unique: e692b4c2-2654-11e3-bc34-90e6baa255ea(36) with data sized (118) -> libgearman-server/server.cc:607 DEBUG 2013-09-26 02:39:47.032239 [
4 ] Received RUN wakeup event -> libgearman-server/gearmand_thread.cc:607 DEBUG 2013-09-26 02:39:47.032254 [ 4 ] GEAR length: 118 gearmand_command_t: GEARMAN_COMMAND_JOB_ASSIGN_ALL -> libgearman-server/plugins/protocol/gear/protocol.cc:274 DEBUG 2013-09-26 02:39:47.032290 [ 4 ] send() 192 bytes to peer 192.168.1.70:39219 -> libgearman-server/io.cc:275 DEBUG 2013-09-26 02:39:47.032303 [ 4 ] Sent JOB_ASSIGN_ALL to 192.168.1.70:-1201209827 -> libgearman-server/thread.cc:365 DEBUG 2013-09-26 02:39:47.034398 [ 4 ] 192.168.1.70:39219 Ready
POLLIN -> libgearman-server/gearmand_con.cc:118 DEBUG 2013-09-26 02:39:47.034416 [ 4 ] read 1926 bytes -> libgearman-server/io.cc:686 INFO 2013-09-26 02:39:47.034427 [ 4 ] Gear unpack DEBUG 2013-09-26 02:39:47.034438 [ 4 ] GEAR length: 1900 gearmand_command_t: GEARMAN_COMMAND_WORK_COMPLETE -> libgearman-server/plugins/protocol/gear/protocol.cc:248 DEBUG 2013-09-26 02:39:47.034462 [ 4 ] Received WORK_COMPLETE 192.168.1.70:3093757469 -> libgearman-server/thread.cc:318 DEBUG 2013-09-26 02:39:47.034479 [ 4 ] 192.168.1.70:39219 Watching POLLIN -> libgearman-server/gearmand_thread.cc:151 DEBUG 2013-09-26 02:39:47.034485 [ proc ] 192.168.1.70:39219 packet command WORK_COMPLETE -> libgearman-server/server.cc:98 DEBUG 2013-09-26 02:39:47.034526 [ 3 ] Received RUN wakeup event -> libgearman-server/gearmand_thread.cc:607 DEBUG 2013-09-26 02:39:47.034542 [ 3 ] GEAR length: 1900 gearmand_command_t: GEARMAN_COMMAND_WORK_COMPLETE -> libgearman-server/plugins/protocol/gear/protocol.cc:274 DEBUG 2013-09-26 02:39:47.034577 [ 3 ] send() 1926 bytes to peer 192.168.1.70:39280 -> libgearman-server/io.cc:275 DEBUG 2013-09-26 02:39:47.034591 [ 3 ] Sent WORK_COMPLETE to 192.168.1.70:-1201208395 -> libgearman-serve
r/thread.cc:365
