Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

VFO frequency caching issue with < 100 Hz steps #539

Closed
mikaelnousiainen opened this issue Feb 8, 2021 · 1 comment
Closed

VFO frequency caching issue with < 100 Hz steps #539

mikaelnousiainen opened this issue Feb 8, 2021 · 1 comment
Labels
bug needs test Patches have been submitted but need testing to close issue

Comments

@mikaelnousiainen
Copy link
Contributor

The VFO frequency caching somehow interferes with frequencies read from rig. At least all Icom backends (not sure if all other backends are affected too) return outdated frequency data for about 1 second after changing the frequency to something that is not a multiple of 100.

See the following log:

Rig command: F 3699020
rigctl_parse: input_line: F 3699020
rigctl_parse: vfo_opt=0
rig_set_freq called vfo=currVFO, freq=3699020
vfo_fixup: vfo=currVFO
vfo_fixup: Leaving currVFO alone
rig_set_freq: TARGETABLE_FREQ vfo=currVFO
icom_set_freq called currVFO=3699020.000000
icom_set_freq: currVFO asked for so vfo set to currVFO
icom_set_freq: set_vfo_curr=currVFO
set_vfo_curr: vfo=currVFO, curr_vfo=currVFO
set_vfo_curr: Asking for currVFO,  currVFO=currVFO
set_vfo_curr: using curr_vfo=currVFO
set_vfo_curr: curr_vfo now=currVFO
rig_get_freq called vfo=currVFO
vfo_fixup: vfo=currVFO
vfo_fixup: Leaving currVFO alone
get_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 1612819356,37632416
elapsed_ms: elapsed_msecs=12883
get_cache_freq: vfo=currVFO, freq=3699010
rig.c(1495):get_cache_freq return
rig_get_freq: cache check1 age=12883ms
rig_get_freq: cache miss age=12883ms, cached_vfo=currVFO, asked_vfo=currVFO
icom_get_freq called for currVFO, curr_vfo=currVFO
set_vfo_curr: vfo=currVFO, curr_vfo=currVFO
set_vfo_curr: Asking for currVFO,  currVFO=currVFO
set_vfo_curr: using curr_vfo=currVFO
set_vfo_curr: curr_vfo now=currVFO
icom_get_freq: using vfo=currVFO
icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0
rig_flush: called for serial device
serial_flush called
tcflush
write_block called
write_block(): TX 6 bytes
0000    fe fe 94 e0 03 fd                                   ......
read_string called, rxmax=80
read_string(): RX 11 characters
0000    fe fe e0 94 03 10 90 69 03 00 fd                    .......i...
icom_one_transaction: data_len=6, frm_len=11
frame.c(334):icom_transaction return
from_bcd called
icom_get_freq exit vfo=currVFO, curr_vfo=currVFO
set_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819368,924356691
rig.c(1425):set_cache_freq return
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819368,924400357
rig_get_freq: cache reset age=999000ms, vfo=currVFO, freq=3699010
set_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819368,924502814
rig.c(1425):set_cache_freq return
rig.c(1839):rig_get_freq return
to_bcd called
icom_transaction: cmd=0x05, subcmd=0xffffffff, payload_len=5
rig_flush: called for serial device
serial_flush called
tcflush
write_block called
write_block(): TX 11 bytes
0000    fe fe 94 e0 05 20 90 69 03 00 fd                    ..... .i...
read_string called, rxmax=80
read_string(): RX 6 characters
0000    fe fe e0 94 fb fd                                   ......
icom_one_transaction: data_len=1, frm_len=6
frame.c(334):icom_transaction return
elapsed_ms: start = 1612819368,924400357
elapsed_ms: elapsed_msecs=10000
rig_get_freq called vfo=currVFO
vfo_fixup: vfo=currVFO
vfo_fixup: Leaving currVFO alone
get_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 1612819368,924502814
elapsed_ms: elapsed_msecs=3
get_cache_freq: vfo=currVFO, freq=3699010
rig.c(1495):get_cache_freq return
rig_get_freq: cache check1 age=2ms
rig_get_freq: currVFO cache hit age=2ms, freq=3699010
rig.c(1740):rig_get_freq return
rig_set_freq: Asked freq=3699020g, got freq=3699010g
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819368,927661983
set_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819368,927806689
rig.c(1425):set_cache_freq return
rig.c(1644):rig_set_freq return
rigctl_parse: vfo_opt=0
rigctl_parse: retcode=0
rigctl_parse: called, interactive=1

Rig command: f
rigctl_parse: input_line: f
rigctl_parse: vfo_opt=0
rig_get_freq called vfo=currVFO
vfo_fixup: vfo=currVFO
vfo_fixup: Leaving currVFO alone
get_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 1612819368,927806689
elapsed_ms: elapsed_msecs=396
get_cache_freq: vfo=currVFO, freq=3699010
rig.c(1495):get_cache_freq return
rig_get_freq: cache check1 age=396ms
rig_get_freq: currVFO cache hit age=396ms, freq=3699010
rig.c(1740):rig_get_freq return
Frequency: 3699010
rigctl_parse: vfo_opt=0
rigctl_parse: retcode=0
rigctl_parse: called, interactive=1

Rig command: f
rigctl_parse: input_line: f
rigctl_parse: vfo_opt=0
rig_get_freq called vfo=currVFO
vfo_fixup: vfo=currVFO
vfo_fixup: Leaving currVFO alone
get_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 1612819368,927806689
elapsed_ms: elapsed_msecs=858
get_cache_freq: vfo=currVFO, freq=3699010
rig.c(1495):get_cache_freq return
rig_get_freq: cache check1 age=857ms
rig_get_freq: cache miss age=857ms, cached_vfo=currVFO, asked_vfo=currVFO
icom_get_freq called for currVFO, curr_vfo=currVFO
set_vfo_curr: vfo=currVFO, curr_vfo=currVFO
set_vfo_curr: Asking for currVFO,  currVFO=currVFO
set_vfo_curr: using curr_vfo=currVFO
set_vfo_curr: curr_vfo now=currVFO
icom_get_freq: using vfo=currVFO
icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0
rig_flush: called for serial device
serial_flush called
tcflush
write_block called
write_block(): TX 6 bytes
0000    fe fe 94 e0 03 fd                                   ......
read_string called, rxmax=80
read_string(): RX 11 characters
0000    fe fe e0 94 03 20 90 69 03 00 fd                    ..... .i...
icom_one_transaction: data_len=6, frm_len=11
frame.c(334):icom_transaction return
from_bcd called
icom_get_freq exit vfo=currVFO, curr_vfo=currVFO
set_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819369,788513409
rig.c(1425):set_cache_freq return
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819369,788572409
rig_get_freq: cache reset age=999000ms, vfo=currVFO, freq=3699020
set_cache_freq:  vfo=currVFO, current_vfo=currVFO
elapsed_ms: start = 0,0
elapsed_ms: after gettime, start = 1612819369,788686574
rig.c(1425):set_cache_freq return
rig.c(1839):rig_get_freq return
Frequency: 3699020
rigctl_parse: vfo_opt=0
rigctl_parse: retcode=0
rigctl_parse: called, interactive=1
@mdblack98 mdblack98 added the bug label Feb 8, 2021
@mdblack98 mdblack98 added this to the 4.2 milestone Feb 8, 2021
mdblack98 added a commit that referenced this issue Feb 9, 2021
@mdblack98
Add a little debug to rig.c
a23a3b4 
#539
mdblack98 added a commit that referenced this issue Feb 10, 2021
@mdblack98
Add resetting of all VFO caches via set_cache_freq using RIG_VFO_ALL
5b59868 
#539
@mdblack98 mdblack98 added the needs test Patches have been submitted but need testing to close issue label Feb 11, 2021
@mikaelnousiainen
Copy link
Contributor Author

@mdblack98 Thanks, the cache invalidation code seems to fix the issue. Tested on both IC-7300 and IC-7600.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug needs test Patches have been submitted but need testing to close issue
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mikaelnousiainen @mdblack98