#888 Inaccurate TPF

[iceman1992]

I notice that the Estimated TPF on my v7 varies wildly.
It's now working on a project 8013, progress nearing 50%.
If I see the log, the TPF is quite constant, around 1:22-1:26.
But the Estimated TPF oscillates between 1:09 and 1:46. So it's either 1:09 or 1:46.

[Leonardo]

That feature of V7 is not yet ready for prime time, from the posts I've seen from other users. I recommend HFM.net for monitoring Folding. Free, it's now available for both the older clients as well as V7.

[iceman1992]

Well I usually see the log anyway. But bruce said that this kind of behavior is unusual, so I posted here. Can't it just take an average of the TPF on the log?

[Jesse_V]

Well I usually see the log anyway. But bruce said that this kind of behavior is unusual, so I posted here. Can't it just take an average of the TPF on the log?

Well no, because if someone fires up something that takes significant CPU power, F@h will back down, which changes it's TPF and ETA. I believe the client takes the last three TPFs, takes the median (not the mean) and reports that as the TPF and uses that for ETA calculations. I've seen fluctuations as well, so maybe there's some kind of glitch somewhere.

[Leonardo]

But bruce said that this kind of behavior is unusual

I apologize for giving inaccurate information.

[iceman1992]

I believe the client takes the last three TPFs, takes the median (not the mean) and reports that as the TPF and uses that for ETA calculations. I've seen fluctuations as well, so maybe there's some kind of glitch somewhere.

I don't believe so.
Because the TPF on mine is around 1:24 +/- 2 seconds, and the client never shows a TPF anywhere near that.
Always the low end (1:09 +/- 2s), or the high end (1:45 +/- 2s).

But an interesting thing to note is this happens on 8013, while on another project like 7809 the TPF is spot on.

[iceman1992]

But bruce said that this kind of behavior is unusual

I apologize for giving inaccurate information.

I'm not saying either of you is inaccurate. Probably different computers and WUs give different results

[Jesse_V]

I believe the client takes the last three TPFs, takes the median (not the mean) and reports that as the TPF and uses that for ETA calculations. I've seen fluctuations as well, so maybe there's some kind of glitch somewhere.

I don't believe so.
Because the TPF on mine is around 1:24 +/- 2 seconds, and the client never shows a TPF anywhere near that.
Always the low end (1:09 +/- 2s), or the high end (1:45 +/- 2s).

But an interesting thing to note is this happens on 8013, while on another project like 7809 the TPF is spot on.

Hmm. From https://fah-web.stanford.edu/projects/F ... ticket/395 ("Improve ETA calculation") which is now marked as closed:

As of v7.1.44 the client tries to measure frames by watching the frame number change. If the core is shutdown or the machine is hibernated the core will detect this and adjust it's estimate accordingly. It saves the last three frame measures and uses the median value for it's predictions. This both allows the estimates to adjust quickly (on a per frame basis) and provides some smoothing for abnormal values.

[cooking]

It saves the last three frame measures and uses the median value for it's predictions. This both allows the estimates to adjust quickly (on a per frame basis) and provides some smoothing for abnormal values.

[Joe_H]

Sometime in the last month or so bruce had posted that they thought the TPF calculations had been fixed, but that he was getting some reports that it still was varying. I don't know how many he has seen. All I know is that using the OS X client (which has multiple issues more critical) there has been no sign the TPF issue was fixed. The TPF estimates I have seen all have fluctuated one side or the other from the actual average. Rarely with the WU mix I have processed has it been real close. It is worse during periods when other processing is active, but still alternates from too high to too low when only F@H is active. I don't take much notice of it normally as I usually leave the FAHControl window closed.

[iceman1992]

To Jesse_V, cooking, and Joe_H. Here I post the log for another 8013 I just completed. The client always shows around 1:08 and 1:42 for this one.
Ignore the part after I clicked finish. Because the antivirus service kicked in just about then, slowing things down a lot for about 5 frames.
I don't understand how the client showed such erratic readings, if it took the median of the last 3 TPFs.

Code: Select all

******************************** Date: 04/05/12 ********************************
13:31:35:WU00:FS01:Connecting to assign3.stanford.edu:8080
13:31:36:WU00:FS01:News: Welcome to Folding@Home
13:31:36:WU00:FS01:Assigned to work server 171.67.108.60
13:31:36:WU00:FS01:Requesting new work unit for slot 01: READY smp:4 from 171.67.108.60
13:31:36:WU00:FS01:Connecting to 171.67.108.60:8080
13:31:38:WU00:FS01:Downloading 866.49KiB
13:31:42:WU00:FS01:Download complete
13:31:42:WU00:FS01:Received Unit: id:00 state:DOWNLOAD error:OK project:8013 run:212 clone:5 gen:2 core:0xa4 unit:0x000000046652edcc4f72bed75503ede3
13:31:43:WU00:FS01:Starting
13:31:43:WU00:FS01:Running FahCore: "J:\Program Files (x86)\FAHClient/FAHCoreWrapper.exe" J:/ProgramData/FAHClient/cores/www.stanford.edu/~pande/Win32/AMD64/Core_a4.fah/FahCore_a4.exe -dir 00 -suffix 01 -version 701 -lifeline 488 -checkpoint 15 -np 4
13:31:43:WU00:FS01:Started FahCore on PID 7444
13:31:44:WU00:FS01:Core PID:4036
13:31:44:WU00:FS01:FahCore 0xa4 started
13:31:45:WU00:FS01:0xa4:
13:31:45:WU00:FS01:0xa4:*------------------------------*
13:31:45:WU00:FS01:0xa4:Folding@Home Gromacs GB Core
13:31:45:WU00:FS01:0xa4:Version 2.27 (Dec. 15, 2010)
13:31:45:WU00:FS01:0xa4:
13:31:45:WU00:FS01:0xa4:Preparing to commence simulation
13:31:45:WU00:FS01:0xa4:- Looking at optimizations...
13:31:45:WU00:FS01:0xa4:- Created dyn
13:31:45:WU00:FS01:0xa4:- Files status OK
13:31:45:WU00:FS01:0xa4:- Expanded 886771 -> 2028636 (decompressed 228.7 percent)
13:31:45:WU00:FS01:0xa4:Called DecompressByteArray: compressed_data_size=886771 data_size=2028636, decompressed_data_size=2028636 diff=0
13:31:45:WU00:FS01:0xa4:- Digital signature verified
13:31:45:WU00:FS01:0xa4:
13:31:45:WU00:FS01:0xa4:Project: 8013 (Run 212, Clone 5, Gen 2)
13:31:45:WU00:FS01:0xa4:
13:31:45:WU00:FS01:0xa4:Assembly optimizations on if available.
13:31:45:WU00:FS01:0xa4:Entering M.D.
13:31:51:WU00:FS01:0xa4:Mapping NT from 4 to 4
13:31:51:WU00:FS01:0xa4:Completed 0 out of 250000 steps  (0%)
13:33:20:WU00:FS01:0xa4:Completed 2500 out of 250000 steps  (1%)
13:34:43:WU00:FS01:0xa4:Completed 5000 out of 250000 steps  (2%)
13:36:07:WU00:FS01:0xa4:Completed 7500 out of 250000 steps  (3%)
13:37:29:WU00:FS01:0xa4:Completed 10000 out of 250000 steps  (4%)
13:38:51:WU00:FS01:0xa4:Completed 12500 out of 250000 steps  (5%)
13:40:14:WU00:FS01:0xa4:Completed 15000 out of 250000 steps  (6%)
13:41:36:WU00:FS01:0xa4:Completed 17500 out of 250000 steps  (7%)
13:42:58:WU00:FS01:0xa4:Completed 20000 out of 250000 steps  (8%)
13:44:20:WU00:FS01:0xa4:Completed 22500 out of 250000 steps  (9%)
13:45:42:WU00:FS01:0xa4:Completed 25000 out of 250000 steps  (10%)
13:47:05:WU00:FS01:0xa4:Completed 27500 out of 250000 steps  (11%)
13:48:27:WU00:FS01:0xa4:Completed 30000 out of 250000 steps  (12%)
13:49:49:WU00:FS01:0xa4:Completed 32500 out of 250000 steps  (13%)
13:51:11:WU00:FS01:0xa4:Completed 35000 out of 250000 steps  (14%)
13:52:34:WU00:FS01:0xa4:Completed 37500 out of 250000 steps  (15%)
13:53:56:WU00:FS01:0xa4:Completed 40000 out of 250000 steps  (16%)
13:55:18:WU00:FS01:0xa4:Completed 42500 out of 250000 steps  (17%)
13:56:41:WU00:FS01:0xa4:Completed 45000 out of 250000 steps  (18%)
13:58:03:WU00:FS01:0xa4:Completed 47500 out of 250000 steps  (19%)
13:59:26:WU00:FS01:0xa4:Completed 50000 out of 250000 steps  (20%)
14:00:48:WU00:FS01:0xa4:Completed 52500 out of 250000 steps  (21%)
14:02:11:WU00:FS01:0xa4:Completed 55000 out of 250000 steps  (22%)
14:03:34:WU00:FS01:0xa4:Completed 57500 out of 250000 steps  (23%)
14:04:57:WU00:FS01:0xa4:Completed 60000 out of 250000 steps  (24%)
14:06:19:WU00:FS01:0xa4:Completed 62500 out of 250000 steps  (25%)
14:07:41:WU00:FS01:0xa4:Completed 65000 out of 250000 steps  (26%)
14:09:03:WU00:FS01:0xa4:Completed 67500 out of 250000 steps  (27%)
14:10:26:WU00:FS01:0xa4:Completed 70000 out of 250000 steps  (28%)
14:11:48:WU00:FS01:0xa4:Completed 72500 out of 250000 steps  (29%)
14:13:10:WU00:FS01:0xa4:Completed 75000 out of 250000 steps  (30%)
14:14:33:WU00:FS01:0xa4:Completed 77500 out of 250000 steps  (31%)
14:15:55:WU00:FS01:0xa4:Completed 80000 out of 250000 steps  (32%)
14:17:17:WU00:FS01:0xa4:Completed 82500 out of 250000 steps  (33%)
14:18:40:WU00:FS01:0xa4:Completed 85000 out of 250000 steps  (34%)
14:20:02:WU00:FS01:0xa4:Completed 87500 out of 250000 steps  (35%)
14:21:25:WU00:FS01:0xa4:Completed 90000 out of 250000 steps  (36%)
14:22:47:WU00:FS01:0xa4:Completed 92500 out of 250000 steps  (37%)
14:24:09:WU00:FS01:0xa4:Completed 95000 out of 250000 steps  (38%)
14:25:32:WU00:FS01:0xa4:Completed 97500 out of 250000 steps  (39%)
14:26:54:WU00:FS01:0xa4:Completed 100000 out of 250000 steps  (40%)
14:28:16:WU00:FS01:0xa4:Completed 102500 out of 250000 steps  (41%)
14:29:39:WU00:FS01:0xa4:Completed 105000 out of 250000 steps  (42%)
14:31:02:WU00:FS01:0xa4:Completed 107500 out of 250000 steps  (43%)
14:32:25:WU00:FS01:0xa4:Completed 110000 out of 250000 steps  (44%)
14:33:49:WU00:FS01:0xa4:Completed 112500 out of 250000 steps  (45%)
14:35:11:WU00:FS01:0xa4:Completed 115000 out of 250000 steps  (46%)
14:36:33:WU00:FS01:0xa4:Completed 117500 out of 250000 steps  (47%)
14:37:56:WU00:FS01:0xa4:Completed 120000 out of 250000 steps  (48%)
14:39:18:WU00:FS01:0xa4:Completed 122500 out of 250000 steps  (49%)
14:40:40:WU00:FS01:0xa4:Completed 125000 out of 250000 steps  (50%)
14:42:02:WU00:FS01:0xa4:Completed 127500 out of 250000 steps  (51%)
14:43:24:WU00:FS01:0xa4:Completed 130000 out of 250000 steps  (52%)
14:44:47:WU00:FS01:0xa4:Completed 132500 out of 250000 steps  (53%)
14:46:09:WU00:FS01:0xa4:Completed 135000 out of 250000 steps  (54%)
14:47:31:WU00:FS01:0xa4:Completed 137500 out of 250000 steps  (55%)
14:48:54:WU00:FS01:0xa4:Completed 140000 out of 250000 steps  (56%)
14:50:47:WU00:FS01:0xa4:Completed 142500 out of 250000 steps  (57%)
14:51:07:FS01:Finishing
14:53:20:WU00:FS01:0xa4:Completed 145000 out of 250000 steps  (58%)
14:55:50:WU00:FS01:0xa4:Completed 147500 out of 250000 steps  (59%)
14:58:10:WU00:FS01:0xa4:Completed 150000 out of 250000 steps  (60%)
15:00:22:WU00:FS01:0xa4:Completed 152500 out of 250000 steps  (61%)
15:01:45:WU00:FS01:0xa4:Completed 155000 out of 250000 steps  (62%)
15:03:07:WU00:FS01:0xa4:Completed 157500 out of 250000 steps  (63%)
15:04:30:WU00:FS01:0xa4:Completed 160000 out of 250000 steps  (64%)
15:05:53:WU00:FS01:0xa4:Completed 162500 out of 250000 steps  (65%)
15:07:16:WU00:FS01:0xa4:Completed 165000 out of 250000 steps  (66%)
15:08:38:WU00:FS01:0xa4:Completed 167500 out of 250000 steps  (67%)
15:10:01:WU00:FS01:0xa4:Completed 170000 out of 250000 steps  (68%)
15:11:23:WU00:FS01:0xa4:Completed 172500 out of 250000 steps  (69%)
15:12:45:WU00:FS01:0xa4:Completed 175000 out of 250000 steps  (70%)
15:14:07:WU00:FS01:0xa4:Completed 177500 out of 250000 steps  (71%)
15:15:29:WU00:FS01:0xa4:Completed 180000 out of 250000 steps  (72%)
15:16:51:WU00:FS01:0xa4:Completed 182500 out of 250000 steps  (73%)
15:18:13:WU00:FS01:0xa4:Completed 185000 out of 250000 steps  (74%)
15:19:35:WU00:FS01:0xa4:Completed 187500 out of 250000 steps  (75%)
15:20:57:WU00:FS01:0xa4:Completed 190000 out of 250000 steps  (76%)
15:22:20:WU00:FS01:0xa4:Completed 192500 out of 250000 steps  (77%)
15:23:42:WU00:FS01:0xa4:Completed 195000 out of 250000 steps  (78%)
15:25:12:WU00:FS01:0xa4:Completed 197500 out of 250000 steps  (79%)
15:27:03:WU00:FS01:0xa4:Completed 200000 out of 250000 steps  (80%)
15:29:07:WU00:FS01:0xa4:Completed 202500 out of 250000 steps  (81%)
15:30:36:WU00:FS01:0xa4:Completed 205000 out of 250000 steps  (82%)
15:31:58:WU00:FS01:0xa4:Completed 207500 out of 250000 steps  (83%)
15:33:23:WU00:FS01:0xa4:Completed 210000 out of 250000 steps  (84%)
15:34:46:WU00:FS01:0xa4:Completed 212500 out of 250000 steps  (85%)
15:36:09:WU00:FS01:0xa4:Completed 215000 out of 250000 steps  (86%)
15:37:31:WU00:FS01:0xa4:Completed 217500 out of 250000 steps  (87%)
15:38:55:WU00:FS01:0xa4:Completed 220000 out of 250000 steps  (88%)
15:40:17:WU00:FS01:0xa4:Completed 222500 out of 250000 steps  (89%)
15:41:40:WU00:FS01:0xa4:Completed 225000 out of 250000 steps  (90%)
15:43:02:WU00:FS01:0xa4:Completed 227500 out of 250000 steps  (91%)
15:44:25:WU00:FS01:0xa4:Completed 230000 out of 250000 steps  (92%)
15:45:47:WU00:FS01:0xa4:Completed 232500 out of 250000 steps  (93%)
15:47:10:WU00:FS01:0xa4:Completed 235000 out of 250000 steps  (94%)
15:48:32:WU00:FS01:0xa4:Completed 237500 out of 250000 steps  (95%)
15:49:55:WU00:FS01:0xa4:Completed 240000 out of 250000 steps  (96%)
15:51:18:WU00:FS01:0xa4:Completed 242500 out of 250000 steps  (97%)
15:52:40:WU00:FS01:0xa4:Completed 245000 out of 250000 steps  (98%)
15:54:02:WU00:FS01:0xa4:Completed 247500 out of 250000 steps  (99%)
15:55:25:WU00:FS01:0xa4:Completed 250000 out of 250000 steps  (100%)
15:55:25:WU00:FS01:0xa4:DynamicWrapper: Finished Work Unit: sleep=10000
15:55:35:WU00:FS01:0xa4:
15:55:35:WU00:FS01:0xa4:Finished Work Unit:
15:55:35:WU00:FS01:0xa4:- Reading up to 1297284 from "00/wudata_01.trr": Read 1297284
15:55:35:WU00:FS01:0xa4:trr file hash check passed.
15:55:35:WU00:FS01:0xa4:- Reading up to 785600 from "00/wudata_01.xtc": Read 785600
15:55:35:WU00:FS01:0xa4:xtc file hash check passed.
15:55:35:WU00:FS01:0xa4:edr file hash check passed.
15:55:35:WU00:FS01:0xa4:logfile size: 23009
15:55:35:WU00:FS01:0xa4:Leaving Run
15:55:38:WU00:FS01:0xa4:- Writing 2111297 bytes of core data to disk...
15:55:38:WU00:FS01:0xa4:Done: 2110785 -> 2024704 (compressed to 95.9 percent)
15:55:38:WU00:FS01:0xa4:  ... Done.
15:55:39:WU00:FS01:0xa4:- Shutting down core
15:55:39:WU00:FS01:0xa4:
15:55:39:WU00:FS01:0xa4:Folding@home Core Shutdown: FINISHED_UNIT
15:55:39:WU00:FS01:FahCore returned: FINISHED_UNIT (100 = 0x64)
15:55:39:WU00:FS01:Sending unit results: id:00 state:SEND error:OK project:8013 run:212 clone:5 gen:2 core:0xa4 unit:0x000000046652edcc4f72bed75503ede3
15:55:39:WU00:FS01:Uploading 1.93MiB to 171.67.108.60
15:55:39:WU00:FS01:Connecting to 171.67.108.60:8080
15:55:45:WU00:FS01:Upload 9.71%
15:55:52:WU00:FS01:Upload 19.42%
15:55:58:WU00:FS01:Upload 29.12%
15:56:05:WU00:FS01:Upload 38.83%
15:56:11:WU00:FS01:Upload 48.54%
15:56:17:WU00:FS01:Upload 58.25%
15:56:23:WU00:FS01:Upload 67.96%
15:56:30:WU00:FS01:Upload 77.66%
15:56:36:WU00:FS01:Upload 87.37%
15:56:43:WU00:FS01:Upload 97.08%
15:56:47:WU00:FS01:Upload complete
15:56:47:WU00:FS01:Server responded WORK_ACK (400)
15:56:47:WU00:FS01:Final credit estimate, 1321.00 points
15:56:47:WU00:FS01:Cleaning up


[bruce]

TPF used to be really bad. The word "fixed" is a matter of degree. The ticket was closed because it was improved quite significantly from what it used to be.

When iceman1992 mentioned the problem, I asked him for details. He's reporting a variation of +- 13% which is more than it should be in a released version but it's probably close enough for a beta version with a number of other issues that should be fixed first.

FAHClient calculates the numbers from some internal data that we don't see rather than the 1% frame messages that appear in the log. (I don't know where it's actually getting the raw data or how frequently.) As has already been reported, HFM seems to do a lot better job of smoothing the data or uses a better source of information. We've asked for the code that makes those calculations to be published and the developer said it would be ... so 3rd party developers can suggest improvements ... but that hasn't happened yet.

[bruce]

13:31:51:Completed 0 out of 250000 steps (0%)
13:33:20:Completed 2500 out of 250000 steps (1%)
13:34:43:Completed 5000 out of 250000 steps (2%)
13:36:07:Completed 7500 out of 250000 steps (3%)
13:37:29:Completed 10000 out of 250000 steps (4%)
13:38:51:Completed 12500 out of 250000 steps (5%)
13:40:14:Completed 15000 out of 250000 steps (6%)
13:41:36:Completed 17500 out of 250000 steps (7%)
13:42:58:Completed 20000 out of 250000 steps (8%)
13:44:20:Completed 22500 out of 250000 steps (9%)
13:45:42:Completed 25000 out of 250000 steps (10%)

Time -- Frame -- Median
1:29 -- 1
1:23 -- 2
1:24 -- 3 -- 1:24
1:22 -- 4 -- 1:23
1:22 -- 5 -- 1:22
1:23 -- 6 -- 1:22
1:22 -- 7 -- 1:22
1:22 -- 8 -- 1:22
1:22 -- 9 -- 1:22
1:22 --10 -- 1:22

I don't see any basis for a +- 13% variation, even when the resolution of the measurements is +- 0.5 sec out of 82 sec or just over +- 0.6% of that. Most WUs have longer frames, so the errors due to measurment resolution errors would be even less significant.

I absolutely do not understand the client always "showing around 1:08 and 1:42 for this one" or in this case +-22%

New ticket #888

[Leonardo]

HFM.net, you'll like it.

[iceman1992]

I don't see any basis for a +- 13% variation, even when the resolution of the measurements is +- 0.5 sec out of 82 sec or just over +- 0.6% of that. Most WUs have longer frames, so the errors due to measurment resolution errors would be even less significant.

That is exactly what I thought

HFM.net, you'll like it.

Thanks for the suggestion but I don't really mind, I use the log for accurate estimations. I'm just reporting the problem, as it may annoy some people