search

bmwcarit / barefoot

Java map matching library for integrating the map into software and services with state-of-the-art online and offline map matching that can be used stand-alone and in the cloud.
Apache License 2.0
664 stars 185 forks source link

Tracker Server timeout #112

Closed ghazalehnt closed 5 years ago

ghazalehnt commented 6 years ago

I'm running the tracker server with this properties:

server.port=1234
server.timeout.request=500
server.timeout.response=1500
server.connections=100
matcher.sigma=5
matcher.lambda=0.0
matcher.distance.max=5000
matcher.radius.max=200
matcher.interval.min=500
matcher.distance.min=0
matcher.threads=8
tracker.state.ttl=60
tracker.port=1235

And sending sample data to it using this script, 10 per second (sleep(0.1)):

while True:
        for sample in samples:
            now = datetime.datetime.now()
            sample["time"] =  now.strftime("%Y-%m-%d %H:%M:%S.%f")[:-3]

            print("Sample: " + json.dumps(sample))
            subprocess.call("echo '%s' | netcat %s %s" % (json.dumps(sample), thost, tport), shell=True)
            time.sleep(0.1)

After some times the sending data is slowing down to less than 10 points per second: 

Sample: {"id": "\\x0001", "time": "2018-07-10 14:32:27.850", "point": "POINT(8.505579 45.90969)"} 
Sample: {"id": "\\x0001", "time": "2018-07-10 14:32:28.936", "point": "POINT(8.505572 45.9097)"}
Sample: {"id": "\\x0001", "time": "2018-07-10 14:32:30.379", "point": "POINT(8.505566 45.90972)"}
Sample: {"id": "\\x0001", "time": "2018-07-10 14:32:31.469", "point": "POINT(8.505557 45.90973)"}

And after about 10 mins it starts to response in timeout:

2018-07-10 11:25:50,255 INFO  [main] AbstractServer: listening on port 1234 ...
2018-07-10 11:37:15,524 ERROR [Thread-3530] AbstractServer: 127.0.0.1:18810 response handler timeout
2018-07-10 11:37:58,616 ERROR [Thread-3565] AbstractServer: 127.0.0.1:18880 response handler timeout
2018-07-10 11:38:01,395 ERROR [Thread-3567] AbstractServer: 127.0.0.1:18884 response handler timeout
2018-07-10 11:40:23,448 ERROR [Thread-3695] AbstractServer: 127.0.0.1:19140 response handler timeout

Any idea why is this happening?

Thanks :)

smattheis commented 6 years ago

Could you please provide some more information?

ghazalehnt commented 6 years ago

Thanks for the reply, of course here are in info: Here is the complete tracker server output until I stopped it:

2018-07-11 11:39:09,860 INFO  [main] TrackerControl: initialize server
2018-07-11 11:39:09,861 INFO  [main] TrackerControl: read database properties from file config/baveno.properties
2018-07-11 11:39:09,863 INFO  [main] Loader: load map from file /home/mrk/barefoot/baveno.bfmap
2018-07-11 11:39:09,921 INFO  [main] RoadMap: inserting roads ...
2018-07-11 11:39:09,957 INFO  [main] RoadMap: inserted 2616 (4706) roads and finished
2018-07-11 11:39:09,992 INFO  [main] RoadMap: ~0 megabytes used for road data (estimate)
2018-07-11 11:39:10,010 INFO  [main] RoadMap: index and topology constructing ...
2018-07-11 11:39:10,102 INFO  [main] RoadMap: index and topology constructed
2018-07-11 11:39:10,128 INFO  [main] RoadMap: ~1 megabytes used for spatial index (estimate)
2018-07-11 11:39:10,128 INFO  [main] TrackerControl: read tracker properties from file config/tracker.properties
2018-07-11 11:39:10,170 INFO  [main] TrackerServer: tracker.state.ttl=60
2018-07-11 11:39:10,171 INFO  [main] TrackerServer: tracker.port=1235
2018-07-11 11:39:10,171 INFO  [main] TrackerServer: tracker.monitor.sensitive=0.0
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.radius.max=200.0
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.distance.max=5000.0
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.lambda=0.0
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.sigma=5.0
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.threads=8
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.interval.min=500
2018-07-11 11:39:10,232 INFO  [main] TrackerServer: matcher.distance.min=0.0
2018-07-11 11:39:10,232 INFO  [main] AbstractServer: server.port=1234
2018-07-11 11:39:10,232 INFO  [main] AbstractServer: server.timeout.request=500
2018-07-11 11:39:10,232 INFO  [main] AbstractServer: server.timeout.response=1500
2018-07-11 11:39:10,232 INFO  [main] AbstractServer: server.connections=100
2018-07-11 11:39:10,232 INFO  [main] TrackerControl: starting server on port 1234 with map baveno
2018-07-11 11:39:10,233 INFO  [main] AbstractServer: listening on port 1234 ...
2018-07-11 11:50:36,229 ERROR [Thread-3534] AbstractServer: 127.0.0.1:29396 response handler timeout
2018-07-11 11:50:39,013 ERROR [Thread-3536] AbstractServer: 127.0.0.1:29400 response handler timeout
2018-07-11 11:50:42,987 ERROR [Thread-3539] AbstractServer: 127.0.0.1:29406 response handler timeout
2018-07-11 11:54:21,794 ERROR [Thread-3735] AbstractServer: 127.0.0.1:29828 response handler timeout
2018-07-11 11:54:23,398 ERROR [Thread-3736] AbstractServer: 127.0.0.1:29830 response handler timeout
2018-07-11 11:54:25,000 ERROR [Thread-3737] AbstractServer: 127.0.0.1:29832 response handler timeout
2018-07-11 11:54:33,645 ERROR [Thread-3744] AbstractServer: 127.0.0.1:29846 response handler timeout
2018-07-11 11:54:39,278 ERROR [Thread-3748] AbstractServer: 127.0.0.1:29854 response handler timeout
2018-07-11 11:54:40,881 ERROR [Thread-3749] AbstractServer: 127.0.0.1:29856 response handler timeout
2018-07-11 11:55:19,110 ERROR [Thread-3780] AbstractServer: 127.0.0.1:29918 response handler timeout
2018-07-11 11:55:29,756 ERROR [Thread-3788] AbstractServer: 127.0.0.1:29934 response handler timeout
2018-07-11 11:55:31,359 ERROR [Thread-3789] AbstractServer: 127.0.0.1:29936 response handler timeout
2018-07-11 11:57:32,894 ERROR [Thread-3888] AbstractServer: 127.0.0.1:30294 response handler timeout
2018-07-11 11:57:38,074 ERROR [Thread-3892] AbstractServer: 127.0.0.1:30302 response handler timeout
2018-07-11 11:58:09,126 ERROR [Thread-3915] AbstractServer: 127.0.0.1:30364 response handler timeout
2018-07-11 11:58:12,034 ERROR [Thread-3917] AbstractServer: 127.0.0.1:30368 response handler timeout
2018-07-11 11:58:27,978 ERROR [Thread-3929] AbstractServer: 127.0.0.1:30392 response handler timeout
2018-07-11 12:01:56,076 ERROR [Thread-4088] AbstractServer: 127.0.0.1:30808 response handler timeout
2018-07-11 12:07:55,183 ERROR [Thread-5166] AbstractServer: 127.0.0.1:33028 response handler timeout
2018-07-11 12:08:08,432 ERROR [Thread-5176] AbstractServer: 127.0.0.1:33048 response handler timeout
2018-07-11 12:08:10,035 ERROR [Thread-5177] AbstractServer: 127.0.0.1:33050 response handler timeout
2018-07-11 12:08:11,638 ERROR [Thread-5178] AbstractServer: 127.0.0.1:33052 response handler timeout
2018-07-11 12:08:14,683 ERROR [Thread-5180] AbstractServer: 127.0.0.1:33056 response handler timeout
2018-07-11 12:08:26,605 ERROR [Thread-5188] AbstractServer: 127.0.0.1:33072 response handler timeout
2018-07-11 12:08:32,603 ERROR [Thread-5192] AbstractServer: 127.0.0.1:33080 response handler timeout
2018-07-11 12:08:34,206 ERROR [Thread-5193] AbstractServer: 127.0.0.1:33082 response handler timeout
2018-07-11 12:08:35,810 ERROR [Thread-5194] AbstractServer: 127.0.0.1:33084 response handler timeout
2018-07-11 12:08:37,414 ERROR [Thread-5195] AbstractServer: 127.0.0.1:33086 response handler timeout
2018-07-11 12:08:40,532 ERROR [Thread-5197] AbstractServer: 127.0.0.1:33090 response handler timeout
2018-07-11 12:08:42,139 ERROR [Thread-5198] AbstractServer: 127.0.0.1:33092 response handler timeout
2018-07-11 12:08:43,743 ERROR [Thread-5199] AbstractServer: 127.0.0.1:33094 response handler timeout
2018-07-11 12:08:45,346 ERROR [Thread-5200] AbstractServer: 127.0.0.1:33096 response handler timeout
2018-07-11 12:08:46,949 ERROR [Thread-5201] AbstractServer: 127.0.0.1:33098 response handler timeout
2018-07-11 12:08:48,552 ERROR [Thread-5202] AbstractServer: 127.0.0.1:33100 response handler timeout
2018-07-11 12:08:50,155 ERROR [Thread-5203] AbstractServer: 127.0.0.1:33102 response handler timeout
2018-07-11 12:08:51,759 ERROR [Thread-5204] AbstractServer: 127.0.0.1:33104 response handler timeout
2018-07-11 12:08:53,362 ERROR [Thread-5205] AbstractServer: 127.0.0.1:33106 response handler timeout
2018-07-11 12:08:54,965 ERROR [Thread-5206] AbstractServer: 127.0.0.1:33108 response handler timeout
2018-07-11 12:08:56,569 ERROR [Thread-5207] AbstractServer: 127.0.0.1:33110 response handler timeout
2018-07-11 12:08:58,172 ERROR [Thread-5208] AbstractServer: 127.0.0.1:33112 response handler timeout
2018-07-11 12:08:59,775 ERROR [Thread-5209] AbstractServer: 127.0.0.1:33114 response handler timeout
2018-07-11 12:09:01,378 ERROR [Thread-5210] AbstractServer: 127.0.0.1:33116 response handler timeout
2018-07-11 12:09:02,981 ERROR [Thread-5211] AbstractServer: 127.0.0.1:33118 response handler timeout
2018-07-11 12:09:04,588 ERROR [Thread-5212] AbstractServer: 127.0.0.1:33120 response handler timeout
2018-07-11 12:09:06,192 ERROR [Thread-5213] AbstractServer: 127.0.0.1:33122 response handler timeout
2018-07-11 12:09:07,795 ERROR [Thread-5214] AbstractServer: 127.0.0.1:33124 response handler timeout
2018-07-11 12:09:09,398 ERROR [Thread-5215] AbstractServer: 127.0.0.1:33126 response handler timeout
2018-07-11 12:09:11,002 ERROR [Thread-5216] AbstractServer: 127.0.0.1:33128 response handler timeout
2018-07-11 12:09:12,605 ERROR [Thread-5217] AbstractServer: 127.0.0.1:33130 response handler timeout
2018-07-11 12:09:12,679 ERROR [pool-2-thread-97] Group: group com.bmwcarit.barefoot.scheduler.Group@4943dc3a sync interrupted, gets cancelled
2018-07-11 12:09:12,683 ERROR [pool-2-thread-97] TrackerServer: matcher execution error
2018-07-11 12:09:14,208 ERROR [Thread-5218] AbstractServer: 127.0.0.1:33132 response handler timeout
2018-07-11 12:09:15,811 ERROR [Thread-5219] AbstractServer: 127.0.0.1:33134 response handler timeout
2018-07-11 12:09:17,414 ERROR [Thread-5220] AbstractServer: 127.0.0.1:33136 response handler timeout
2018-07-11 12:09:19,018 ERROR [Thread-5221] AbstractServer: 127.0.0.1:33138 response handler timeout
2018-07-11 12:09:20,621 ERROR [Thread-5222] AbstractServer: 127.0.0.1:33140 response handler timeout
2018-07-11 12:09:22,224 ERROR [Thread-5223] AbstractServer: 127.0.0.1:33142 response handler timeout
2018-07-11 12:09:23,827 ERROR [Thread-5224] AbstractServer: 127.0.0.1:33144 response handler timeout
2018-07-11 12:09:25,430 ERROR [Thread-5225] AbstractServer: 127.0.0.1:33146 response handler timeout
2018-07-11 12:09:27,033 ERROR [Thread-5226] AbstractServer: 127.0.0.1:33148 response handler timeout
2018-07-11 12:09:28,637 ERROR [Thread-5227] AbstractServer: 127.0.0.1:33162 response handler timeout
2018-07-11 12:09:30,240 ERROR [Thread-5228] AbstractServer: 127.0.0.1:33164 response handler timeout
2018-07-11 12:09:30,290 ERROR [pool-2-thread-21] Group: group com.bmwcarit.barefoot.scheduler.Group@796a9f4 sync interrupted, gets cancelled
2018-07-11 12:09:30,290 ERROR [pool-2-thread-21] TrackerServer: matcher execution error
2018-07-11 12:09:31,843 ERROR [Thread-5229] AbstractServer: 127.0.0.1:33166 response handler timeout
2018-07-11 12:09:33,446 ERROR [Thread-5230] AbstractServer: 127.0.0.1:33168 response handler timeout
2018-07-11 12:09:35,049 ERROR [Thread-5231] AbstractServer: 127.0.0.1:33170 response handler timeout
2018-07-11 12:09:36,653 ERROR [Thread-5232] AbstractServer: 127.0.0.1:33172 response handler timeout
2018-07-11 12:09:38,256 ERROR [Thread-5233] AbstractServer: 127.0.0.1:33174 response handler timeout
2018-07-11 12:09:39,859 ERROR [Thread-5234] AbstractServer: 127.0.0.1:33176 response handler timeout
2018-07-11 12:09:41,462 ERROR [Thread-5235] AbstractServer: 127.0.0.1:33178 response handler timeout
2018-07-11 12:09:41,464 ERROR [pool-2-thread-34] Group: group com.bmwcarit.barefoot.scheduler.Group@56d4ec28 sync interrupted, gets cancelled
2018-07-11 12:09:41,464 ERROR [pool-2-thread-34] TrackerServer: matcher execution error
2018-07-11 12:09:43,065 ERROR [Thread-5236] AbstractServer: 127.0.0.1:33180 response handler timeout
2018-07-11 12:09:44,668 ERROR [Thread-5237] AbstractServer: 127.0.0.1:33182 response handler timeout
2018-07-11 12:09:46,271 ERROR [Thread-5238] AbstractServer: 127.0.0.1:33184 response handler timeout
2018-07-11 12:09:47,874 ERROR [Thread-5239] AbstractServer: 127.0.0.1:33186 response handler timeout
2018-07-11 12:09:49,477 ERROR [Thread-5240] AbstractServer: 127.0.0.1:33188 response handler timeout
2018-07-11 12:09:51,080 ERROR [Thread-5241] AbstractServer: 127.0.0.1:33190 response handler timeout
2018-07-11 12:09:52,683 ERROR [Thread-5242] AbstractServer: 127.0.0.1:33192 response handler timeout
2018-07-11 12:09:54,286 ERROR [Thread-5243] AbstractServer: 127.0.0.1:33194 response handler timeout
2018-07-11 12:09:55,889 ERROR [Thread-5244] AbstractServer: 127.0.0.1:33196 response handler timeout
2018-07-11 12:09:57,492 ERROR [Thread-5245] AbstractServer: 127.0.0.1:33198 response handler timeout
2018-07-11 12:09:59,095 ERROR [Thread-5246] AbstractServer: 127.0.0.1:33200 response handler timeout
2018-07-11 12:09:59,095 ERROR [pool-2-thread-55] Group: group com.bmwcarit.barefoot.scheduler.Group@17ba1d2c sync interrupted, gets cancelled
2018-07-11 12:09:59,096 ERROR [pool-2-thread-55] TrackerServer: matcher execution error
2018-07-11 12:10:00,698 ERROR [Thread-5247] AbstractServer: 127.0.0.1:33202 response handler timeout
2018-07-11 12:10:02,302 ERROR [Thread-5248] AbstractServer: 127.0.0.1:33204 response handler timeout
2018-07-11 12:10:03,905 ERROR [Thread-5249] AbstractServer: 127.0.0.1:33206 response handler timeout
2018-07-11 12:10:05,508 ERROR [Thread-5250] AbstractServer: 127.0.0.1:33208 response handler timeout
2018-07-11 12:10:07,112 ERROR [Thread-5251] AbstractServer: 127.0.0.1:33210 response handler timeout
2018-07-11 12:10:08,715 ERROR [Thread-5252] AbstractServer: 127.0.0.1:33212 response handler timeout
2018-07-11 12:10:10,318 ERROR [Thread-5253] AbstractServer: 127.0.0.1:33214 response handler timeout
2018-07-11 12:10:11,921 ERROR [Thread-5254] AbstractServer: 127.0.0.1:33216 response handler timeout
2018-07-11 12:10:11,986 ERROR [pool-2-thread-73] Group: group com.bmwcarit.barefoot.scheduler.Group@db884d2 sync interrupted, gets cancelled
2018-07-11 12:10:11,992 ERROR [pool-2-thread-73] TrackerServer: matcher execution error
2018-07-11 12:10:13,524 ERROR [Thread-5255] AbstractServer: 127.0.0.1:33218 response handler timeout
2018-07-11 12:10:15,127 ERROR [Thread-5256] AbstractServer: 127.0.0.1:33220 response handler timeout
2018-07-11 12:10:16,730 ERROR [Thread-5257] AbstractServer: 127.0.0.1:33222 response handler timeout
2018-07-11 12:10:18,334 ERROR [Thread-5258] AbstractServer: 127.0.0.1:33224 response handler timeout
2018-07-11 12:10:25,833 INFO  [Thread-0] TrackerControl: stopping server
2018-07-11 12:10:25,833 INFO  [Thread-0] AbstractServer: received shutdown signal
2018-07-11 12:10:25,833 INFO  [Thread-0] AbstractServer: closing server ...
2018-07-11 12:10:25,835 INFO  [main] AbstractServer: **closed**

The memory usage: at 12:00:

             total       used       free     shared    buffers     cached
Mem:         15998      11168       4830        134        642       3081
-/+ buffers/cache:       7444       8554
Swap:         3905          0       3905

at 12:10 before stopping the server:

             total       used       free     shared    buffers     cached
Mem:         15998      11370       4628        135        642       3083
-/+ buffers/cache:       7644       8353
Swap:         3905          0       3905

The data is in baveno (italy), here is the sample data file, the times are set using the script in my previous post: baveno.json.txt

ghazalehnt commented 6 years ago

I also tried using subprocess.Popen("echo '%s' | netcat %s %s" % (json.dumps(sample), thost, tport), shell=True) instead of subprocess.call to avoid waiting and after some time running it will cause this:

2018-07-11 14:50:21,745 INFO  [main] AbstractServer: listening on port 1234 ...
2018-07-11 14:55:59,513 WARN  [pool-2-thread-9] TrackerServer: received out of order sample
2018-07-11 14:55:59,514 WARN  [pool-2-thread-4] TrackerServer: received out of order sample
2018-07-11 14:55:59,514 WARN  [pool-2-thread-8] TrackerServer: received out of order sample
2018-07-11 14:56:00,080 WARN  [pool-2-thread-20] TrackerServer: received out of order sample
2018-07-11 14:56:00,080 WARN  [pool-2-thread-12] TrackerServer: received out of order sample
2018-07-11 14:56:00,080 WARN  [pool-2-thread-15] TrackerServer: received out of order sample
2018-07-11 14:56:00,080 WARN  [pool-2-thread-16] TrackerServer: received out of order sample
2018-07-11 14:56:00,658 WARN  [pool-2-thread-38] TrackerServer: received out of order sample
2018-07-11 14:56:00,659 WARN  [pool-2-thread-22] TrackerServer: received out of order sample
2018-07-11 14:56:00,658 WARN  [pool-2-thread-27] TrackerServer: received out of order sample
2018-07-11 14:56:00,658 WARN  [pool-2-thread-30] TrackerServer: received out of order sample
2018-07-11 14:56:00,660 WARN  [pool-2-thread-23] TrackerServer: received out of order sample
2018-07-11 14:56:01,253 WARN  [pool-2-thread-43] TrackerServer: received out of order sample
2018-07-11 14:56:01,254 WARN  [pool-2-thread-32] TrackerServer: received out of order sample
2018-07-11 14:56:01,254 WARN  [pool-2-thread-35] TrackerServer: received out of order sample
2018-07-11 14:56:01,254 WARN  [pool-2-thread-39] TrackerServer: received out of order sample
2018-07-11 14:56:01,253 WARN  [pool-2-thread-42] TrackerServer: received out of order sample
2018-07-11 14:56:01,922 WARN  [pool-2-thread-55] TrackerServer: received out of order sample
2018-07-11 14:56:01,922 WARN  [pool-2-thread-50] TrackerServer: received out of order sample
2018-07-11 14:56:01,922 WARN  [pool-2-thread-44] TrackerServer: received out of order sample
2018-07-11 14:56:01,922 WARN  [pool-2-thread-57] TrackerServer: received out of order sample
2018-07-11 14:56:01,922 WARN  [pool-2-thread-58] TrackerServer: received out of order sample
2018-07-11 14:56:02,613 WARN  [pool-2-thread-63] TrackerServer: received out of order sample
2018-07-11 14:56:02,613 WARN  [pool-2-thread-60] TrackerServer: received out of order sample
2018-07-11 14:56:02,613 WARN  [pool-2-thread-64] TrackerServer: received out of order sample
2018-07-11 14:56:02,613 WARN  [pool-2-thread-65] TrackerServer: received out of order sample
2018-07-11 14:56:02,613 WARN  [pool-2-thread-67] TrackerServer: received out of order sample
2018-07-11 14:56:03,294 WARN  [pool-2-thread-83] TrackerServer: received out of order sample
2018-07-11 14:56:03,295 WARN  [pool-2-thread-80] TrackerServer: received out of order sample
2018-07-11 14:56:03,295 WARN  [pool-2-thread-74] TrackerServer: received out of order sample
2018-07-11 14:56:03,295 WARN  [pool-2-thread-75] TrackerServer: received out of order sample
2018-07-11 14:56:03,295 WARN  [pool-2-thread-78] TrackerServer: received out of order sample
2018-07-11 14:56:03,295 WARN  [pool-2-thread-72] TrackerServer: received out of order sample
2018-07-11 14:56:04,073 WARN  [pool-2-thread-95] TrackerServer: received out of order sample
2018-07-11 14:56:04,073 WARN  [pool-2-thread-97] TrackerServer: received out of order sample
2018-07-11 14:56:04,073 WARN  [pool-2-thread-92] TrackerServer: received out of order sample
2018-07-11 14:56:04,073 WARN  [pool-2-thread-87] TrackerServer: received out of order sample
2018-07-11 14:56:04,074 WARN  [pool-2-thread-85] TrackerServer: received out of order sample
2018-07-11 14:56:04,073 WARN  [pool-2-thread-90] TrackerServer: received out of order sample
2018-07-11 14:56:04,866 ERROR [Thread-3368] AbstractServer: 127.0.0.1:39656 response handler timeout
2018-07-11 14:56:04,915 WARN  [pool-2-thread-18] TrackerServer: received out of order sample
2018-07-11 14:56:04,915 WARN  [pool-2-thread-7] TrackerServer: received out of order sample
2018-07-11 14:56:04,915 WARN  [pool-2-thread-93] TrackerServer: received out of order sample
2018-07-11 14:56:04,915 WARN  [pool-2-thread-5] TrackerServer: received out of order sample
2018-07-11 14:56:04,915 WARN  [pool-2-thread-11] TrackerServer: received out of order sample
2018-07-11 14:56:04,915 WARN  [pool-2-thread-17] TrackerServer: received out of order sample
2018-07-11 14:56:05,592 ERROR [Thread-3375] AbstractServer: 127.0.0.1:39670 response handler timeout
2018-07-11 14:56:05,677 ERROR [Thread-3376] AbstractServer: 127.0.0.1:39672 response handler timeout
2018-07-11 14:56:05,706 WARN  [pool-2-thread-16] TrackerServer: received out of order sample
2018-07-11 14:56:05,706 WARN  [pool-2-thread-3] TrackerServer: received out of order sample
2018-07-11 14:56:05,706 WARN  [pool-2-thread-8] TrackerServer: received out of order sample
2018-07-11 14:56:05,706 WARN  [pool-2-thread-12] TrackerServer: received out of order sample
smattheis commented 6 years ago

Thanks for the information. I used your data to reproduce the use case. The bad news is that it took me a while to find the root cause for the increasing latency, the good news is that it can be fixed easily. In detail, my observations are as follows:

  1. I modified the submit script with the code snippet that you provided. However, the line 
    sample["time"] =  now.strftime("%Y-%m-%d %H:%M:%S.%f")[:-3]

    results in an exception for each sample like this Unparseable date: "2018-07-13 16:24:55.450". Therefore, I changed it to

    sample["time"] = int(round(time.time() * 1000))

    which provides the time in milliseconds unix time, suitable to represent time in resolution of less than one second.

  2. The map matching doesn't slow down, you can check that yourself if you add this:

    <logger name="com.bmwcarit.barefoot.tracker.TrackerServer"
    level="DEBUG" additivity="false">
    <appender-ref ref="CONSOLE" />
</logger>

    to the logger configuration in src/main/resources/logback.xml and repackage the JAR with mvn package -DskipTests. Instead, the slow down comes from sending state updates to the monitor: Since you push updates with approx. 5-10 Hz into the matcher for a time of several minutes, the matching state grows to thousands of samples to represent the full history of the object. This is not the actual problem, but rather in combination with the rudimentary implementation of the pipeline between tracker server and monitor, which was designed to only illustrate the real-time map matching use case. The problem is that the tracker server sends the complete state in JSON format to the monitor with each update. This is the case even if you do not use the monitor as it publishes it on a ZeroMQ PUB socket which doesn't care if there is a listener connected to it.

    The solution to your problem depends on your use case:

    1. If you want to use the monitor, you should bound the matcher state in time. In my test, I used 60 seconds and the latency of each iteration was bound to a maximum of around 100 milliseconds, 50 milliseconds in average. To do that, you need to edit one line in the code, here: https://github.com/bmwcarit/barefoot/blob/master/src/main/java/com/bmwcarit/barefoot/tracker/TrackerServer.java#L263(I should add a configuration option to make that easier.) 
      final MatcherKState inner = new MatcherKState(-1, 60000);
    2. If you don't want to use the monitor, replace the StatePublisher here: https://github.com/bmwcarit/barefoot/blob/master/src/main/java/com/bmwcarit/barefoot/tracker/TrackerServer.java#L270 with something that suits your use case. (For the records, the slow is caused lines 299-301 here: https://github.com/bmwcarit/barefoot/blob/master/src/main/java/com/bmwcarit/barefoot/tracker/TrackerServer.java#L299-301)
  3. A minor note to your code snippet, you send samples with 5-10 Hertz. However, you've also configured matcher.interval.min=500 which means that the tracker omits all samples below a time interval of 500 milliseconds after the last matched sample. That means, sending samples with 5-10 Hz is useless with this configuration as it enforces 2 Hz. For testing, I've set matcher.interval.min=0 to follow the rate of your code snippet. Moreover, in your code snippet, with time.sleep (0.1) after the submission of a sample you cannot ensure a fixed rate because the rate depends on the synchronous submission of the sample such that it varies, as said, around 5-10 Hz. The stream submit script submits samples also with best effort but no faster than the rate of timestamps provided with the samples. You could adapt that script to fix a submission rate in the way that you wait adaptively according to the latency of each execution and omit a sample if the execution took more than second.
smattheis commented 6 years ago

@ghazalehnt Does it solve the issue for you?

ghazalehnt commented 5 years ago

Hi @smattheis, sorry for the late reply and thank you very much for this complete and helpful answer. I tried limiting the returned state and it worked perfectly.