search

AravisProject / aravis

A vision library for genicam based cameras
GNU Lesser General Public License v2.1
861 stars 321 forks source link

Correctly implement Cachable #253

Closed EmmanuelP closed 4 years ago

EmmanuelP commented 5 years ago

The code that is supposed to handle register cache in arvgcregisternode.c is broken:

MarkRivers commented 5 years ago

I am happy to test this when someone has time to work on it. My aravis installation is already a git clone, so I can easily pull new changes to test the performance.

I am curious why a problem with register caching causes some enum features to take a very long time to read, while others are very fast? For example on the FLIR Oryx 51S5M it takes about 700 ms and 3500 GcRegisterNode::_get_integer_value messages when reading the 15 enum values and strings for TriggerSource. However, it takes less than 1 ms and no GcRegisterNode::_get_integer_value messages when reading the 10 enum values and strings for ChunkPixelFormat.

There is also a very large difference between USB and 10 GigE cameras. On the USB camera is takes less than 100 ms to read all of the features, compared to 1 to 12 seconds on GigE and 10 GigE. Is the USB bus read time that much faster when reading registers?

EmmanuelP commented 5 years ago

TriggerSource and ChunkPixelFormat declarations in the genicam are not the same:

   <Enumeration Name="ChunkPixelFormat" NameSpace="Standard">
      <ToolTip>Format of the pixel provided by the camera</ToolTip>
      <Description>Format of the pixel provided by the camera</Description>
      <DisplayName>Chunk Pixel Format</DisplayName>
      <Visibility>Expert</Visibility>
      <pIsLocked>ChunkSelector_PixelFormat_Imp</pIsLocked>
      <EnumEntry Name="Mono8" NameSpace="Standard">
         <DisplayName>Mono8</DisplayName>
         <Value>0x01080001</Value>
      </EnumEntry>
      <EnumEntry Name="Mono12Packed" NameSpace="Standard">
         <DisplayName>Mono12Packed</DisplayName>
         <Value>0x010C0006</Value>
      </EnumEntry>
      <EnumEntry Name="Mono16" NameSpace="Standard">
         <DisplayName>Mono16</DisplayName>
         <Value>0x01100007</Value>
      </EnumEntry>
      <EnumEntry Name="RGB8Packed" NameSpace="Standard">
         <DisplayName>RGB8Packed</DisplayName>
         <Value>0x02180014</Value>
      </EnumEntry>
      <EnumEntry Name="YUV422Packed" NameSpace="Standard">
         <DisplayName>YUV422Packed</DisplayName>
         <Value>0x0210001F</Value>
      </EnumEntry>
      <EnumEntry Name="BayerGR8" NameSpace="Standard">
         <DisplayName>BayerGR8</DisplayName>
         <Value>0x01080008</Value>
      </EnumEntry>
      <EnumEntry Name="BayerRG8" NameSpace="Standard">
         <DisplayName>BayerRG8</DisplayName>
         <Value>0x01080009</Value>
      </EnumEntry>
      <EnumEntry Name="BayerGB8" NameSpace="Standard">
         <DisplayName>BayerGB8</DisplayName>
         <Value>0x0108000A</Value>
      </EnumEntry>
      <EnumEntry Name="BayerBG8" NameSpace="Standard">
         <DisplayName>BayerBG8</DisplayName>
         <Value>0x0108000B</Value>
      </EnumEntry>
      <EnumEntry Name="YCbCr601_422_8_CbYCrY" NameSpace="Standard">
         <DisplayName>YCbCr601_422_8_CbYCrY</DisplayName>
         <Value>0x02100044</Value>
      </EnumEntry>
      <pValue>ChunkPixelFormat_Val</pValue>
   </Enumeration>
   <Enumeration Name="TriggerSource" NameSpace="Standard">
      <ToolTip>Specifies the internal signal or physical input line to use as the trigger source.</ToolTip>
      <Description>Specifies the internal signal or physical input line to use as the trigger source.</Description>
      <DisplayName>Trigger Source</DisplayName>
      <Visibility>Beginner</Visibility>
      <pIsImplemented>TriggerSource_Imp</pIsImplemented>
      <pIsAvailable>TriggerSource_Avl</pIsAvailable>
      <pIsLocked>TriggerSource_Lck</pIsLocked>
      <ImposedAccessMode>RW</ImposedAccessMode>
      <EnumEntry Name="Software" NameSpace="Standard">
         <DisplayName>Software</DisplayName>
         <pIsImplemented>TriggerSource_Software_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Software_Avl</pIsAvailable>
         <Value>31</Value>
      </EnumEntry>
      <EnumEntry Name="Line0" NameSpace="Standard">
         <DisplayName>Line 0</DisplayName>
         <pIsImplemented>TriggerSource_Line0_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line0_Avl</pIsAvailable>
         <Value>0</Value>
      </EnumEntry>
      <EnumEntry Name="Line1" NameSpace="Standard">
         <DisplayName>Line 1</DisplayName>
         <pIsImplemented>TriggerSource_Line1_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line1_Avl</pIsAvailable>
         <Value>1</Value>
      </EnumEntry>
      <EnumEntry Name="Line2" NameSpace="Standard">
         <DisplayName>Line 2</DisplayName>
         <pIsImplemented>TriggerSource_Line2_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line2_Avl</pIsAvailable>
         <Value>2</Value>
      </EnumEntry>
      <EnumEntry Name="Line3" NameSpace="Standard">
         <DisplayName>Line 3</DisplayName>
         <pIsImplemented>TriggerSource_Line3_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line3_Avl</pIsAvailable>
         <Value>3</Value>
      </EnumEntry>
      <EnumEntry Name="Line4" NameSpace="Standard">
         <DisplayName>Line 4</DisplayName>
         <pIsImplemented>TriggerSource_Line4_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line4_Avl</pIsAvailable>
         <Value>8</Value>
      </EnumEntry>
      <EnumEntry Name="Line5" NameSpace="Standard">
         <DisplayName>Line 5</DisplayName>
         <pIsImplemented>TriggerSource_Line5_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line5_Avl</pIsAvailable>
         <Value>9</Value>
      </EnumEntry>
      <EnumEntry Name="Line6" NameSpace="Standard">
         <DisplayName>Line 6</DisplayName>
         <pIsImplemented>TriggerSource_Line6_Imp</pIsImplemented>
         <pIsAvailable>TriggerSource_Line6_Avl</pIsAvailable>
         <Value>10</Value>
      </EnumEntry>

The Locked, Available and Implemented values are read from registers like this one:

   <MaskedIntReg Name="TriggerSource_Avl">
      <pAddress>TriggerSourceAddr</pAddress>
      <Length>4</Length>
      <AccessMode>RO</AccessMode>
      <pPort>Device</pPort>
      <pInvalidator>ExposureMode_Val</pInvalidator>
      <Bit>1</Bit>
      <Sign>Unsigned</Sign>
      <Endianess>BigEndian</Endianess>
   </MaskedIntReg>

TriggerSourceAddr is defined by:

   <IntSwissKnife Name="TriggerSourceAddr">
      <pVariable Name="SELECTOR_INDEX_0">TriggerSelectorValueToIndex</pVariable>
      <Formula>0x000C8C00 + 0x20 * (  ( SELECTOR_INDEX_0 * 1  )  )</Formula>
   </IntSwissKnife>
   <IntSwissKnife Name="TriggerSelectorValueToIndex">
      <Visibility>Invisible</Visibility>
      <pVariable Name="SWITCH_TARGET">TriggerSelector</pVariable>
      <Formula>( SWITCH_TARGET = 2 ) ? 0 : ( ( SWITCH_TARGET = 3 ) ? 1 : ( ( SWITCH_TARGET = 4 ) ? 2 : 0 )  )</Formula>
   </IntSwissKnife>

And Trigger selector is itself an enum:

   <Enumeration Name="TriggerSelector" NameSpace="Standard">
      <ToolTip>Selects the type of trigger to configure.</ToolTip>
      <Description>Selects the type of trigger to configure.</Description>
      <DisplayName>Trigger Selector</DisplayName>
      <Visibility>Beginner</Visibility>
      <ImposedAccessMode>RW</ImposedAccessMode>
      <EnumEntry Name="AcquisitionStart" NameSpace="Standard">
         <DisplayName>Acquisition Start</DisplayName>
         <pIsImplemented>TriggerSourceAcquisitionStart_Imp</pIsImplemented>
         <pIsAvailable>TriggerSourceAcquisitionStart_Avl</pIsAvailable>
         <Value>2</Value>
      </EnumEntry>
      <EnumEntry Name="FrameStart" NameSpace="Standard">
         <DisplayName>Frame Start</DisplayName>
         <pIsImplemented>TriggerSourceFrameStart_Imp</pIsImplemented>
         <pIsAvailable>TriggerSourceFrameStart_Avl</pIsAvailable>
         <Value>3</Value>
      </EnumEntry>
      <EnumEntry Name="FrameBurstStart" NameSpace="Standard">
         <DisplayName>Frame Burst Start</DisplayName>
         <pIsImplemented>TriggerSourceFrameBurstStart_Imp</pIsImplemented>
         <pIsAvailable>TriggerSourceFrameBurstStart_Avl</pIsAvailable>
         <Value>4</Value>
      </EnumEntry>
      <Value>3</Value>
      <pSelected>TriggerMode</pSelected>
      <pSelected>TriggerSoftware</pSelected>
      <pSelected>TriggerSource</pSelected>
      <pSelected>TriggerActivation</pSelected>
      <pSelected>TriggerOverlap</pSelected>
      <pSelected>TriggerDelay</pSelected>
   </Enumeration>

I have to check, but it is possible the read of the TriggerSelector value may cause a read if its enum entry Implemented and Available properties, which would lead to more register reads. That part could be also improved.

So, in the end, registers are read numerous times, which probably explains the huge numbers you are seeing. Proper caching would help a lot.

Regarding the difference between GigEVision and USB, may be the genicam definition of TriggerSource is simpler.

MarkRivers commented 5 years ago

Thanks for the explanation, that makes sense.

EmmanuelP commented 5 years ago

@MarkRivers I've tried to fix register caching, but I'm not sure I will be able to enable it by default, it looks like most of the devices don't declare correctly the cachable and pInvalidators properties.

The resulting work is in this branch: https://github.com/AravisProject/aravis/tree/wip/cache

There is 3 cache modes: disable, enable and debug, that can be selected using arv_device_set_register_cache_policy.

The viewer takes a -c option for the policy selection.

In the debug mode, the register is always read, whatever the cache validity is, and the resulting read and the cache content is compared. Is they don't match, an error is displayed on the console. When the device is released, a statistic of cache hits and misses is also displayed.

Could you test it please ?

MarkRivers commented 5 years ago

@EmmanuelP thanks for working on this.

I have checked out the wip/cache branch. I am not sure how to build it, with ./configure or meson?

When I use ./configure I get this error:

config.status: creating docs/Makefile
config.status: creating docs/reference/Makefile
config.status: creating docs/reference/aravis/Makefile
config.status: error: cannot find input file: `aravis.pc.in'

When I use meson I get this error:

corvette:/usr/local/aravis>meson build
The Meson build system
Version: 0.47.2
Source dir: /usr/local/aravis
Build dir: /usr/local/aravis/build
Build type: native build
Project name: aravis
Project version: 0.7.0
Native C compiler: cc (gcc 4.8.5 "cc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28)")
Native C++ compiler: c++ (gcc 4.8.5 "c++ (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28)")
Build machine cpu family: x86_64
Build machine cpu: x86_64
Found pkg-config: /bin/pkg-config (0.27.1)
Native dependency glib-2.0 found: YES 2.54.2
Native dependency gobject-2.0 found: YES 2.54.2
Native dependency gio-2.0 found: YES 2.54.2
Native dependency libxml-2.0 found: YES 2.9.1
Native dependency zlib found: YES 1.2.7
Library m found: YES

meson.build:36:1: ERROR:  Native dependency 'audit' not found

A full log can be found at /usr/local/aravis/build/meson-logs/meson-log.txt

I have never used meson before, so this could be something simple. The OS is Centos 7.

MarkRivers commented 5 years ago

I realized that the problem might be that it needed a package called "audit", so I installed that with yum install. 

...
Running transaction check
Running transaction test
Transaction test succeeded
Running transaction
  Updating   : audit-libs-2.8.4-4.el7.x86_64                                                                                                                                          1/6
  Updating   : audit-2.8.4-4.el7.x86_64                                                                                                                                               2/6
  Updating   : audit-libs-2.8.4-4.el7.i686                                                                                                                                            3/6
  Cleanup    : audit-2.8.1-3.el7_5.1.x86_64                                                                                                                                           4/6
  Cleanup    : audit-libs-2.8.1-3.el7_5.1                                                                                                                                             5/6
  Cleanup    : audit-libs-2.8.1-3.el7_5.1                                                                                                                                             6/6
  Verifying  : audit-libs-2.8.4-4.el7.x86_64                                                                                                                                          1/6
  Verifying  : audit-2.8.4-4.el7.x86_64                                                                                                                                               2/6
  Verifying  : audit-libs-2.8.4-4.el7.i686                                                                                                                                            3/6
  Verifying  : audit-libs-2.8.1-3.el7_5.1.x86_64                                                                                                                                      4/6
  Verifying  : audit-2.8.1-3.el7_5.1.x86_64                                                                                                                                           5/6
  Verifying  : audit-libs-2.8.1-3.el7_5.1.i686                                                                                                                                        6/6

Updated:
  audit.x86_64 0:2.8.4-4.el7

Dependency Updated:
  audit-libs.i686 0:2.8.4-4.el7                                                              audit-libs.x86_64 0:2.8.4-4.el7

It seems to have installed OK. However, meson still fails:

corvette:/usr/local/aravis>meson build
The Meson build system
Version: 0.47.2
Source dir: /usr/local/aravis
Build dir: /usr/local/aravis/build
Build type: native build
Project name: aravis
Project version: 0.7.0
Native C compiler: cc (gcc 4.8.5 "cc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28)")
Native C++ compiler: c++ (gcc 4.8.5 "c++ (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28)")
Build machine cpu family: x86_64
Build machine cpu: x86_64
Found pkg-config: /bin/pkg-config (0.27.1)
Native dependency glib-2.0 found: YES 2.54.2
Native dependency gobject-2.0 found: YES 2.54.2
Native dependency gio-2.0 found: YES 2.54.2
Native dependency libxml-2.0 found: YES 2.9.1
Native dependency zlib found: YES 1.2.7
Library m found: YES

meson.build:36:1: ERROR:  Native dependency 'audit' not found

A full log can be found at /usr/local/aravis/build/meson-logs/meson-log.txt

I cannot find a file called audit.pc anywhere in /usr.

EmmanuelP commented 5 years ago

Meson is the one and only build system now. Your configure file is a leftover of the time autotools was still used.

You need the development package of audit: audit-libs-devel

MarkRivers commented 5 years ago

After installing a number of other packages I got "meson build" to work.

I then cd to the build directory. The README.md says to type "ninja" but on Centos7 the command seems to be "ninja-build" not "ninja"?

I then get an error:

corvette:/usr/local/aravis>rm -rf build
corvette:/usr/local/aravis>meson build
The Meson build system
Version: 0.47.2
Source dir: /usr/local/aravis
Build dir: /usr/local/aravis/build
Build type: native build
Project name: aravis
Project version: 0.7.0
Native C compiler: cc (gcc 4.8.5 "cc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28)")
Native C++ compiler: c++ (gcc 4.8.5 "c++ (GCC) 4.8.5 20150623 (Red Hat 4.8.5-28)")
Build machine cpu family: x86_64
Build machine cpu: x86_64
Found pkg-config: /bin/pkg-config (0.27.1)
Native dependency glib-2.0 found: YES 2.54.2
Native dependency gobject-2.0 found: YES 2.54.2
Native dependency gio-2.0 found: YES 2.54.2
Native dependency libxml-2.0 found: YES 2.9.1
Native dependency zlib found: YES 1.2.7
Library m found: YES
Native dependency audit found: YES 2.8.4
Native dependency libusb-1.0 found: YES 1.0.21
Configuring arvfeatures.h using configuration
Configuring arvversion.h using configuration
Native dependency gobject-introspection-1.0 found: YES 1.50.0
Native dependency gtk+-3.0 found: YES 3.22.30
Native dependency gstreamer-base-1.0 found: YES 1.10.4
Native dependency gstreamer-app-1.0 found: YES 1.10.4
Native dependency gstreamer-video-1.0 found: YES 1.10.4
Native dependency libnotify found: YES 0.7.7
Native dependency glib-2.0 found: YES 2.54.2
Configuring arv-viewer-0.8.appdata.xml using configuration
Dependency gstreamer-base-1.0 found: YES (cached)
Dependency gstreamer-app-1.0 found: YES (cached)
Build targets in project: 38
Found ninja-1.7.2 at /bin/ninja-build
corvette:/usr/local/aravis>cd build
/usr/local/aravis/build
corvette:local/aravis/build>ninja-build
[128/130] Linking target viewer/arv-viewer-0.8.
FAILED: viewer/arv-viewer-0.8
cc  -o viewer/arv-viewer-0.8 'viewer/viewer@@arv-viewer-0.8@exe/meson-generated_.._arvviewerresources.c.o' 'viewer/viewer@@arv-viewer-0.8@exe/main.c.o' 'viewer/viewer@@arv-viewer-0.8@exe/arvviewer.c.o' -Wl,--no-undefined -Wl,--as-needed -Wl,--start-group src/libaravis-0.8.so.0.7.0 /usr/lib64/libglib-2.0.so /usr/lib64/libgobject-2.0.so /usr/lib64/libgio-2.0.so /usr/lib64/libxml2.so /usr/lib64/libz.so -lm /lib64/libaudit.so /usr/lib64/libusb-1.0.so /usr/lib64/libgtk-3.so /usr/lib64/libgdk-3.so /usr/lib64/libatk-1.0.so /usr/lib64/libpangocairo-1.0.so /usr/lib64/libgdk_pixbuf-2.0.so /usr/lib64/libcairo-gobject.so /usr/lib64/libpango-1.0.so /usr/lib64/libcairo.so /usr/lib64/libgstbase-1.0.so /usr/lib64/libgstreamer-1.0.so /usr/lib64/libgstapp-1.0.so /usr/lib64/libgstvideo-1.0.so /usr/lib64/libnotify.so -Wl,--end-group '-Wl,-rpath,$ORIGIN/../src:$ORIGIN/../../../../../lib64' -Wl,-rpath-link,/usr/local/aravis/build/src:/lib64
/usr/lib64/libcairo.so: undefined reference to `FT_Get_Var_Design_Coordinates'
/usr/lib64/libcairo.so: undefined reference to `FT_Get_Var_Blend_Coordinates'
collect2: error: ld returned 1 exit status
[129/130] Generating Aravis-0.8.gir with a custom command.
ninja: build stopped: subcommand failed.
corvette:local/aravis/build>ls

Any idea how to fix this? I think it has successfully built the aravis library and arvtool at this point, but it won't install them because of the above error.

MarkRivers commented 5 years ago

I would also be happy to just disable building the arv-viewer for now, but I am not sure which file to edit to do that.

EmmanuelP commented 5 years ago

meson configure -Dviewer=false

EmmanuelP commented 5 years ago

Which distribution are you using ? The undefined reference errors are weird...

EmmanuelP commented 5 years ago

/usr/lib64/libcairo.so: undefined reference to 'FT_Get_Var_Design_Coordinates' /usr/lib64/libcairo.so: undefined reference to 'FT_Get_Var_Blend_Coordinates'

Do you have a custom libfreetype installed somewhere ?

MarkRivers commented 5 years ago

Centos7 is the distribution I am using.

Do you have a custom libfreetype installed somewhere ?

I don't have any in /usr, /lib, or /lib64

1073743164    0 lrwxrwxrwx   1 root     root           21 Oct 23  2017 /usr/lib64/libfreetype.so.6 -> libfreetype.so.6.10.0
1073743165  676 -rwxr-xr-x   1 root     root       691736 Aug  2  2017 /usr/lib64/libfreetype.so.6.10.0
1104140251    0 lrwxrwxrwx   1 root     root           21 Oct 23  2017 /usr/lib64/libfreetype.so -> libfreetype.so.6.10.0
corvette:aravisIOC/aravisApp/src>sudo find /lib -name 'libfreetype*' -ls
corvette:aravisIOC/aravisApp/src>sudo find /lib64 -name 'libfreetype*' -ls

I do have a newer version in the anaconda3 directory in my home directory, but those directories are not in my LD_LIBRARY_PATH or PATH.

2158261691    4 -rwxrwxr-x   1 epics    domain users     1065 Aug 24  2018 /home/epics/anaconda3/pkgs/freetype-2.9.1-h8a8886c_1/lib/libfreetype.la
2158261958    0 lrwxrwxrwx   1 epics    domain users       21 Aug 28  2018 /home/epics/anaconda3/pkgs/freetype-2.9.1-h8a8886c_1/lib/libfreetype.so -> libfreetype.so.6.16.1
2158261959    0 lrwxrwxrwx   1 epics    domain users       21 Aug 28  2018 /home/epics/anaconda3/pkgs/freetype-2.9.1-h8a8886c_1/lib/libfreetype.so.6 -> libfreetype.so.6.16.1
2158261961  760 -rwxrwxr-x   2 epics    domain users   778224 Aug 24  2018 /home/epics/anaconda3/pkgs/freetype-2.9.1-h8a8886c_1/lib/libfreetype.so.6.16.1
2158261962  948 -rw-rw-r--   2 epics    domain users   968668 Aug 24  2018 /home/epics/anaconda3/pkgs/freetype-2.9.1-h8a8886c_1/lib/libfreetype.a
2158261962  948 -rw-rw-r--   2 epics    domain users   968668 Aug 24  2018 /home/epics/anaconda3/lib/libfreetype.a
1078561232    0 lrwxrwxrwx   1 epics    domain users       21 Feb  5  2019 /home/epics/anaconda3/lib/libfreetype.so -> libfreetype.so.6.16.1
1078561233    0 lrwxrwxrwx   1 epics    domain users       21 Feb  5  2019 /home/epics/anaconda3/lib/libfreetype.so.6 -> libfreetype.so.6.16.1
2158261961  760 -rwxrwxr-x   2 epics    domain users   778224 Aug 24  2018 /home/epics/anaconda3/lib/libfreetype.so.6.16.1
1078561231    4 -rwxrwxr-x   1 epics    domain users     1032 Feb  5  2019 /home/epics/anaconda3/lib/libfreetype.la
MarkRivers commented 5 years ago

I tried removing the anaconda3/bin directory from my PATH but that did not fix the error building arv-viewer.

MarkRivers commented 5 years ago

Building with -Dviewer=false allowed the build and install to complete. I can now begin to test my application.

exzombie commented 4 years ago

I was hoping that this would finally solve the slowness of QArv's feature browser, but it has no discernible effect. In particular, color transformation features of Basler-acA1300-30gc are especially problematic (the grayscale version of the same Basler camera responds much more quickly).

Looking at XML dumped from Basler-acA1300-30gc, it only specifies WriteAround and NoCache for a few registers and nothing for most of them, so it seems to me that it assumes WriteThrough as default.

Skimming through arvgcregisternode.c, it seems that arv_gc_register_node_new_* functions set the defaults mostly to WriteThrough (BTW, there's a typo: TRHOUGH), except for floats (WriteAround) and structs (NoCache). But then arv_gc_register_node_init(), which is the function that allocates the cache hash table, sets

gc_register_node->default_cachable = ARV_GC_CACHABLE_NO_CACHE;

Does this mean that the default cacheability is actually NoCache?

EmmanuelP commented 4 years ago

Hi Jure,

Did you enable caching with arv_device_set_register_cache_policy() ?

Does this mean that the default cacheability is actually NoCache?

arv_gc_register_node_init() is executed during object initialization in g_object_new(). default_cachable is overriden in the different arv_gc_register_node_new_*() constructors.

EmmanuelP commented 4 years ago

If you set ARV_DEBUG=genicam, a cache hit/miss statistic will be displayed when the device object is finalized. Something like that:

Cache hits = 1 / 1 for DeviceModelName
Cache hits = 1 / 2 for SensorHeightRegister
Cache hits = 1 / 2 for SensorWidthRegister
Cache hits = 1 / 2 for OffsetXRegister
Cache hits = 1 / 2 for OffsetYRegister
Cache hits = 3 / 4 for WidthRegister
Cache hits = 3 / 4 for HeightRegister
Cache hits = 0 / 1 for BinningHorizontalRegister
Cache hits = 0 / 1 for BinningVerticalRegister
Cache hits = 3 / 4 for PixelFormatRegister
Cache hits = 0 / 1 for AcquisitionFramePeriodRegister
Cache hits = 0 / 1 for ExposureTimeAbsRegister
Cache hits = 0 / 1 for GainRawRegister
Cache hits = 2 / 3 for GainAutoRegister
exzombie commented 4 years ago

arv_gc_register_node_init() is executed during object initialization in g_object_new(). default_cachable is overriden in the different arv_gc_register_nodenew*() constructors.

I see. Shows how little I work with gobject :)

I did set the cache policy, of course, and I also noticed that cache hit stats were printed; they looked good, but the performance was not, which is why I'm looking into it. Sadly, I don't have much time to play with an actual camera.

So in the meantime, I'm trying to understand the code. And AFAICT, arv_gc_port_read is called regardless of whether the value is cached or not. Shouldn't the read only happen under the debug policy?

BTW, cache hit stats are printed on finalization regardless of any debug settings, but they are meaningless without the debug cache policy.

EmmanuelP commented 4 years ago

So in the meantime, I'm trying to understand the code. And AFAICT, arv_gc_port_read is called regardless of whether the value is cached or not. Shouldn't the read only happen under the debug policy?

You are right. I'm going to fix that.

MarkRivers commented 4 years ago

I apologize for not being able to test this sooner.

I have now tested using the FLIR Spinnaker SDK, aravis 0.6.3 and the aravis wip/cache as of October 7, 2019. I test the time to write the ExposureTime feature and then read back the values of all other features. So far I have tested on a GigE BlackkFlyS camera. These are the results:

  BlackFlyS 13Y3M  
SDK Caching  Time (s)
Spinnaker N.A. 0.036
aravis 0.6.3 N.A. 1.569
aravis wip/cache ARV_REGISTER_CACHE_POLICY_DISABLE 6.634
aravis wip/cache ARV_REGISTER_CACHE_POLICY_ENABLE 6.658
aravis wip/cache ARV_REGISTER_CACHE_POLICY_DEBUG 6.610

So Spinnaker takes on 36 ms. With the stable aravis 0.6.3is takes 1.57 seconds. However, with the wip/cache branch it takes 6.6 seconds no matter what value I use for arv_gc_set_register_cache_policy(). I read back and print the actual cache policy to verify that it is being set correctly.

Perhaps I am doing something wrong? Is wip/cache still the branch I should be testing?

EmmanuelP commented 4 years ago

I apologize for not being able to test this sooner.

No need to apologize, I'm happy you are testing aravis.

Is wip/cache still the branch I should be testing?

No, sorry, I should have deleted it. The branch was merged into master a while ago.

Could you re-run your tests using aravis master ?

MarkRivers commented 4 years ago

I have switched to the master branch. I changed the feature set/get calls to add the new GError** argument which I set to NULL.

  BlackFlyS 13Y3M  
SDK Caching Time (s)
ADSpinnaker N.A. 0.036
aravis 0.6.3 N.A. 1.569
aravis wip/cache ARV_REGISTER_CACHE_POLICY_DISABLE 6.634
aravis wip/cache ARV_REGISTER_CACHE_POLICY_ENABLE 6.658
aravis wip/cache ARV_REGISTER_CACHE_POLICY_DEBUG 6.610
     
aravis/master ARV_REGISTER_CACHE_POLICY_DISABLE 6.612
aravis/master ARV_REGISTER_CACHE_POLICY_ENABLE 5.067
aravis/master ARV_REGISTER_CACHE_POLICY_DEBUG 6.627

It looks like that with ENABLE it is a little faster than with the wip/cache branch, but is still more than 3 times slower than the 0.6.3 branch and is more than 100 times slower than Spinnaker.

I ran my application with ARV_DEBUG=genicam:3. This is the output: aravisDebug.txt

EmmanuelP commented 4 years ago

With genicam=3, we should see cache hits/miss debug output when the cache is either enabled or in debug mode. I don't see that in aravisDebug.txt.

Something like that:

Cache hits = 7 / 8 for GainRawAll_Imp
Cache hits = 7 / 8 for GainRawAll_Avl
Cache hits = 1 / 2 for Gain_Val
Cache hits = 0 / 1 for Gain_Min
Cache hits = 0 / 1 for Gain_Max
Cache hits = 2 / 3 for PixelFormat_Val
Cache hits = 4 / 5 for PixelFormat_Mono8_Avl
Cache hits = 4 / 5 for PixelFormat_Mono16_Avl
Cache hits = 4 / 5 for PixelFormat_RGB8Packed_Avl
Cache hits = 4 / 5 for PixelFormat_BayerGR8_Avl
Cache hits = 4 / 5 for PixelFormat_BayerRG8_Avl
Cache hits = 4 / 5 for PixelFormat_BayerGB8_Avl
...
MarkRivers commented 4 years ago

With genicam=3, we should see cache hits/miss debug output when the cache is either enabled or in debug mode. I don't see that in aravisDebug.txt.

Yes, I was wondering about that.

I cannot figure out what I am doing wrong.

I am running the master branch. The aravis version returned with ARAVIS_MAJOR_VERSION, ARAVIS_MINOR_VERSION, ARAVIS_MICRO_VERSION is 0.7.2.

ARV_DEBUG is set as follows:

corvette:aravisIOC/iocBoot/iocAravis>echo $ARV_DEBUG
genicam:3

In my application I print out the value of arv_gc_get_register_cache_policy() whenever an integer feature is being set. In the text file above you will see lines like this:

2019/10/08 09:34:17.349 ADAravis::writeInt32  arv_gc_get_register_cache_policy = 1

This shows that the cache policy is set to Enable (1).

What could be causing the absence of the cache debugging messages?

This is the code where I set the cache policy. I do this as soon as I get the genicam object:

asynStatus ADAravis::makeCameraObject() {
    const char *functionName = "makeCameraObject";
    /* remove old camera if it exists */
    if (this->camera != NULL) {
        g_object_unref(this->camera);
        this->camera = NULL;
    }
    /* remove ref to device and genicam */
    this->device = NULL;
    this->genicam = NULL;

    /* connect to camera */
    printf ("ADAravis: Looking for camera '%s'... \n", this->cameraName);
    this->camera = arv_camera_new (this->cameraName);
    if (this->camera == NULL) {
        asynPrint(this->pasynUserSelf, ASYN_TRACE_ERROR,
                    "%s:%s: No camera found\n",
                    driverName, functionName);
        return asynError;
    }
    /* Store device */
    this->device = arv_camera_get_device(this->camera);
    if (this->device == NULL) {
        asynPrint(this->pasynUserSelf, ASYN_TRACE_ERROR,
                    "%s:%s: No device associated with camera\n",
                    driverName, functionName);
        return asynError;
    }
    if (ARV_IS_GV_DEVICE(this->device)) {
        // Automatically determine optimum packet size
        arv_gv_device_auto_packet_size(ARV_GV_DEVICE(this->device));
        // Uncomment this line to set jumbo packets
        //arv_gv_device_set_packet_size(ARV_GV_DEVICE(this->device), 9000);
    }
    /* Store genicam */
    this->genicam = arv_device_get_genicam (this->device);
    if (this->genicam == NULL) {
        asynPrint(this->pasynUserSelf, ASYN_TRACE_ERROR,
                    "%s:%s: No genicam element associated with camera\n",
                    driverName, functionName);
        return asynError;
    }
    /* Set the cache policy */
    arv_gc_set_register_cache_policy(this->genicam, ARV_REGISTER_CACHE_POLICY_ENABLE);

    return asynSuccess;
}
MarkRivers commented 4 years ago

The previous tests were run on a Centos 7 system with a BlackFlyS GigE camera.

Today I installed the master branch on an Ubuntu 18 system today. I built the same application and tested with an Oryx 10 GigE camera. I ran with cache enabled and ARV_DEBUG=genicam:3. The results are attached here: oryx_debug1.txt

Again I do not see the cache debug messages.

This table shows the time to read all of the features after changing ExposureTime.

  Oryx 10G-51S5M  
SDK Caching  
ADSpinnaker N.A. 0.039
aravis 0.6.3 N.A. 11.819
aravis/master ARV_REGISTER_CACHE_POLICY_ENABLE 5.107

So 0.7.2 with cache enabled is faster than 0.6.3, but much slower than Spinnaker.

EmmanuelP commented 4 years ago

Hi Mark,

I have pushed to master a new feature to arv-tool that shows the values of all the device features, with an optional display of the execution time and the slection of the cache policy.

Please attach the result of:

arv-tool-0.8 values -c disable -t -d genicam values

and

arv-tool-0.8 values -c enable -t -d genicam values

That will help to understand what you get.

Please note the value display is still incomplete, as arv-tool doesn't yet iterate over all the values of the feature pSelected node.

MarkRivers commented 4 years ago

This is the output with disable: arv_tool_disable.txt

This is the output with enable: arv_tool_enable.txt

I see that the cache statistics are printed in the arv_gc_register_node_finalize() function. I am not seeing those messages. When is that method called?

MarkRivers commented 4 years ago

Here are the results for an Oryx camera on Ubuntu 18. arv_tool_oryx_disable.txt arv_tool_oryx_enable.txt

MarkRivers commented 4 years ago

I have now tested with all 3 caching options on both cameras, as well as 0.6.3 and Spinnaker.

BlackFlyS on Centos 7

  BlackFlyS 13Y3M  
SDK Caching Time (s)
ADSpinnaker N.A. 0.036
aravis 0.6.3 N.A. 1.569
aravis/master ARV_REGISTER_CACHE_POLICY_DISABLE 6.612
aravis/master ARV_REGISTER_CACHE_POLICY_DEBUG 6.627
aravis/master ARV_REGISTER_CACHE_POLICY_ENABLE 5.067

Oryx on Ubuntu 18

  Oryx 10G-51S5M  
SDK Caching  Time (s)
ADSpinnaker N.A. 0.039
aravis 0.6.3 N.A. 11.819
aravis/master ARV_REGISTER_CACHE_POLICY_DISABLE 16.930
aravis/master ARV_REGISTER_CACHE_POLICY_DEBUG 16.738
aravis/master ARV_REGISTER_CACHE_POLICY_ENABLE 5.107

Major conclusions:

EmmanuelP commented 4 years ago

I have pushed a fix to master that handle the case of event features, which should improve the overall time of reading all the feature values.

MarkRivers commented 4 years ago

Success!!!

Here is the performance now:

  BlackFlyS 13Y3M  
SDK Caching Time (s)
ADSpinnaker N.A. 0.036
aravis 0.6.3 N.A. 1.569
aravis/master ARV_REGISTER_CACHE_POLICY_DISABLE 1.596
aravis/master ARV_REGISTER_CACHE_POLICY_DEBUG 1.594
aravis/master ARV_REGISTER_CACHE_POLICY_ENABLE 0.062
  Oryx 10G-51S5M  
SDK Caching Time (s)
ADSpinnaker N.A. 0.039
aravis 0.6.3 N.A. 11.819
aravis/master ARV_REGISTER_CACHE_POLICY_DISABLE 11.729
aravis/master ARV_REGISTER_CACHE_POLICY_DEBUG  
aravis/master ARV_REGISTER_CACHE_POLICY_ENABLE 0.096

The performance with caching disabled is now the same as 0.6.3, rather than worse.

With caching the performance improves by factor of 25 for the BlackFlyS and 122 for the Oryx. The times are now very comparable to Spinnaker.

I think aravis is now completely usable for my application.

Thanks very much!

EmmanuelP commented 4 years ago

Ok, let's say cache is implemented almost correctly now.

I'm not activating it by default, because it seems camera genicam data don't always correctly declare the feature node cachable and invalidator properties.

If you find cache related issue, don't hesitate to open a new issue.

Cheers,

Emmanuel.