Slow Database connection
ademarco avatar
drea
I am setting up a fresh installation on a new machine, and give that I've set up Tango a few times now, everything went smoothly. However, contrary to previous experiences, TANGO seems very slow to respond. For example, loading Astor from the command line:

astor
Display is :0.0
====================== ZMQ event system is available ============================
Build GUI :6497 ms
tcp://10.0.2.15:55556 —> tcp://127.0.1.1:55556
Device (sys/database/2) timed out (>3000 ms)!
Device (sys/database/2) timed out (>3000 ms)!
Total time to subscribe on 1 hosts : 6402 ms
Total time to start Astor 11952 ms

I am getting timeouts that I don't usually get. The same goes for accessing a particular device server in Jive, all "works", but it's very slow. If I run commands on a particular device, I get no errors, just a very slow response time. I was wondering if you could give me a checklist for stuff to look out for in my installation…

Thanks :)
Dr Andrea DeMarco, BSc (Hons) (Melita), MSc (Melita), DPhil (UEA)
Lecturer | Researcher
Department of Physics
Institute of Space Sciences and Astronomy

Room 220, Maths and Physics Building
University of Malta, Msida MSD2080, MALTA
avatar par défaut
Manu
Hello,

A list of things which could be checked:
- MySQL release (>5.0)
- Is the stored procedure installed (show procedure status in mysql cmd line) ?
- What about the CPU load?
- Check the database device black box. To do so, open Jive (if you can), then in device tab, select device sys/database/2 and
once selected, right click and "Test device". Go to "Admin" panel. Change the value in BlackBox field (default is 10) to 50 and
click execute. You should have a list of the last command/attribute executed/read on the database device.
Check if you have a lot of activity on this device when your system is "quiet"
- Read the Timing_info attribute on the database device (previous point to get the panel to read this attribute) and check if
one of the reported command takes a very long time.

Hoping one of these advices will help you to find out the reason of your problems.

Good luck

Emmanuel
ademarco avatar
drea
Hello Manu,

Thanks for your help. I can confirm the following:

1) Operating System - Ubuntu 14.04
2) CPU load is very low during execution/connection to DB (e.g. 2-3%)
3) MySQL 5.5 is installed
4) Testing database black box as instructed gives me an Error with timeout > 3000ms. The stack trace is as follows:

fr.esrf.TangoApi.CommunicationTimeout
 at
fr.esrf.TangoDs.Except.throw_communication_timeout(Except.java:789)
fr.esrf.TangoDs.Except.throw_communication_timeout(Except.java:706)
fr.esrf.TangoApi.ConnectionDAODefaultImpl.throw_dev_failed(ConnectionDAODefaultImpl.java:762)
fr.esrf.TangoApi.ConnectionDAODefaultImpl.black_box(ConnectionDAODefaultImpl.java:987)
fr.esrf.TangoApi.Connection.black_box(Connection.java:419)
jive.CommonPanel.actionPerformed(CommonPanel.java:227)
javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:2018)
javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2341)
javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:402)
javax.swing.DefaultButtonModel.setPressed(DefaultButtonModel.java:259)
javax.swing.plaf.basic.BasicButtonListener.mouseReleased(BasicButtonListener.java:252)
java.awt.Component.processMouseEvent(Component.java:6516)
javax.swing.JComponent.processMouseEvent(JComponent.java:3312)
java.awt.Component.processEvent(Component.java:6281)
java.awt.Container.processEvent(Container.java:2229)
java.awt.Component.dispatchEventImpl(Component.java:4872)
java.awt.Container.dispatchEventImpl(Container.java:2287)
java.awt.Component.dispatchEvent(Component.java:4698)
java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4832)
java.awt.LightweightDispatcher.processMouseEvent(Container.java:4492)
java.awt.LightweightDispatcher.dispatchEvent(Container.java:4422)
java.awt.Container.dispatchEventImpl(Container.java:2273)
java.awt.Window.dispatchEventImpl(Window.java:2719)
java.awt.Component.dispatchEvent(Component.java:4698)
java.awt.EventQueue.dispatchEventImpl(EventQueue.java:747)
java.awt.EventQueue.access$300(EventQueue.java:103)
java.awt.EventQueue$3.run(EventQueue.java:706)
java.awt.EventQueue$3.run(EventQueue.java:704)
java.security.AccessController.doPrivileged(Native Method)
java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:77)
java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:87)
java.awt.EventQueue$4.run(EventQueue.java:720)
java.awt.EventQueue$4.run(EventQueue.java:718)
java.security.AccessController.doPrivileged(Native Method)
java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:77)
java.awt.EventQueue.dispatchEvent(EventQueue.java:717)
java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:242)
java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:161)
java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:150)
java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:146)
java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:138)
java.awt.EventDispatchThread.run(EventDispatchThread.java:91)

5) Running commands seem fine e.g.
—————————————————-
Command: sys/database/2/ResetTimingValues
Duration: 1 msec
Command OK
—————————————————-
Command: sys/database/2/State
Duration: 3 msec
Output argument(s) :
ON

6) Reading the timing info seems fine too, and attribute gives the following:
—————————————————-
Attribute: sys/database/2/Timing_info
Duration: 39 msec
measure date: 02/03/2016 15:06:47 + 880ms
quality: VALID
dim x: 30
Read length: 30
Read [0] TANGO Database Timing info on host aavs
Read [1]
Read [2] command average minimum maximum calls
Read [3]
Read [4] DbDeleteDeviceProperty 0.000 0.000 0.000 0
Read [5] DbExportDevice 3.054 0.247 11.203 4
Read [6] DbExportEvent 0.000 0.000 0.000 0
Read [7] DbGetClassPropertyList 0.000 0.000 0.000 0
Read [8] DbGetDataForServerCache 58.936 58.936 58.936 1
Read [9] DbGetDeviceAttributeProperty 0.000 0.000 0.000 0
Read [10] DbGetDeviceAttributeProperty2 0.000 0.000 0.000 0
Read [11] DbGetDeviceClassList 0.000 0.000 0.000 0
Read [12] DbGetDeviceDomainList 0.287 0.287 0.287 1
Read [13] DbGetDeviceExportedList 0.000 0.000 0.000 0
Read [14] DbGetDeviceFamilyList 0.000 0.000 0.000 0
Read [15] DbGetDeviceMemberList 0.000 0.000 0.000 0
Read [16] DbGetDeviceProperty 0.000 0.000 0.000 0
Read [17] DbGetDevicePropertyList 0.000 0.000 0.000 0
Read [18] DbGetHostList 0.000 0.000 0.000 0
Read [19] DbGetHostServerList 0.372 0.372 0.372 1
Read [20] DbGetServerList 0.367 0.233 0.501 2
Read [21] DbImportDevice 0.586 0.403 0.929 5
Read [22] DbImportEvent 0.000 0.000 0.000 0
Read [23] DbInfo 0.775 0.513 1.037 2
Read [24] DbMySqlSelect 0.000 0.000 0.000 0
Read [25] DbPutClassProperty 22.924 22.924 22.924 1
Read [26] DbPutDeviceAttributeProperty 0.000 0.000 0.000 0
Read [27] DbPutDeviceAttributeProperty2 0.000 0.000 0.000 0
Read [28] DbPutDeviceProperty 0.000 0.000 0.000 0
Read [29] DbUnExportServer 0.000 0.000 0.000 0

7) I can run SHOW PROCEDURE STATUS; from mysql command line and it looks ok:

mysql> SHOW PROCEDURE STATUS;
+——-+—————-+———–+—————-+———————+———————+—————+————-+———————-+———————-+——————–+
| Db | Name | Type | Definer | Modified | Created | Security_type | Comment | character_set_client | collation_connection | Database Collation |
+——-+—————-+———–+—————-+———————+———————+—————+————-+———————-+———————-+——————–+
| tango | class_att_prop | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | class_prop | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | dev_att_prop | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | dev_prop | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | ds_start | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | release 1.8 | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | get_dev_list | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | import_device | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | import_event | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
| tango | obj_prop | PROCEDURE | root@localhost | 2016-03-02 14:16:41 | 2016-03-02 14:16:41 | DEFINER | | utf8 | utf8_general_ci | latin1_swedish_ci |
+——-+—————-+———–+—————-+———————+———————+—————+————-+———————-+———————-+——————–+
9 rows in set (0.00 sec)

8) Running some further tests from the following basic python code:

from PyTango import Database, DbDevInfo

def add_device(domain='test_domain', family='GenericDevice', member=1):

    # A reference on the Database
    tic()
    db = Database()
    toc()

    # Define device name
    device_name = domain + "/" + family.lower() + "/" + str(member)

    # Define the Tango Class served by this DServer
    dev_info = DbDevInfo()
    dev_info._class = family
    dev_info.server = family + "/" + domain

    # add the device
    print("Creating device: %s" % device_name)
    dev_info.name = device_name
    tic()
    db.add_device(dev_info)
    toc()

def tic():
    #Homemade version of matlab tic and toc functions
    import time
    global startTime_for_tictoc
    startTime_for_tictoc = time.time()

def toc():
    import time
    if 'startTime_for_tictoc' in globals():
        print "Elapsed time is " + str(time.time() - startTime_for_tictoc) + " seconds."
    else:
        print "Toc: start time not set"

if __name__ == "__main__":
    add_device(domain='test_domain', family='LoggerDS', member=1)

This program gives the following output:
Elapsed time is 10.0089612007 seconds.
Creating device: test_domain/loggerds/1
Elapsed time is 0.0011248588562 seconds.

This means that it's the database connection which is causing trouble, as once we have that, running a command to add the device is no problem at all…

Thanks,
Andrea
Dr Andrea DeMarco, BSc (Hons) (Melita), MSc (Melita), DPhil (UEA)
Lecturer | Researcher
Department of Physics
Institute of Space Sciences and Astronomy

Room 220, Maths and Physics Building
University of Malta, Msida MSD2080, MALTA
ademarco avatar
drea
Hi Manu,

Some additional information that could be useful. If I simply connect to the database via simple python code like:

def test_db_connection():
    # Open database connection
    tic()
    db = MySQLdb.connect("localhost","root","","tango" )


    # prepare a cursor object using cursor() method
    cursor = db.cursor()

    # execute SQL query using execute() method.
    cursor.execute("SELECT VERSION()")

    # Fetch a single row using fetchone() method.
    data = cursor.fetchone()

    print "Database version : %s " % data

    # disconnect from server
    db.close()
    toc()

There are no problems:
Database version : 5.5.47-0ubuntu0.14.04.1
Elapsed time is 0.0074360370636 seconds.

Process finished with exit code 0


Something seems to be wrong with the way Tango is connecting?
Dr Andrea DeMarco, BSc (Hons) (Melita), MSc (Melita), DPhil (UEA)
Lecturer | Researcher
Department of Physics
Institute of Space Sciences and Astronomy

Room 220, Maths and Physics Building
University of Malta, Msida MSD2080, MALTA
agotz avatar
Andy
Hi Andrea,

what version of TANGO have you installed? We had an issue with memorised attributes which could slow down the database a lot. This issue (discussed on the forum) has been resolved. I wonder if you have the old version of the database server which caused the database server to be slowed down.
I noticed in the output for the timing you sent that the command DbPutClass Property is slow:
Read [25] DbPutClassProperty 22.924 22.924 22.924 1

CORRECTION : this is not not slow - it is in milliseconds!

The way the database server is working is that it all requests are executed in their own thread. This explains why the request to read the timing info is fast. However when a request to the database modifies the database it will lock the database. This will slow down other requests to the database. If this is your case the question is which client is writing to the database? You can try to read the blackbox to find this out or check the debugging output.
Some more questions to think about:
    How big is your database? How many devices and servers? When did this start slowing down? Can you upgrade to TANGO 9 at least for the database?
Cheers
Andy
Edited 8 years ago
agotz avatar
Andy
I had another idea - maybe it is just the import of the database that is slow. In this case check your TANGO_HOST and make sure the database is started listening on the right port. There might be a problem with the import which is due to the network address. What command do you use to start the Database server? Send us the output you get with "ps -ef | grep Database" and the TANGO_HOST. Try pinging the hos in TANGO_HOST and make sure this is work correctly. You can also do a dev_ping() on the Database device from a python client and measure the timing.

Andy
ademarco avatar
drea
Hi Andy,

So I am currently working with Tango 8, not Tango 9 - basically more or less the instructions here:
Ubuntu 14.04 Install

I don't have anything else set up on this machine - it's a clean install, with just a dummy device that I've created that does absolutely nothing, and the test devices. No other devices are connected and no other communication is happening. I am working locally and not connecting to a remote host.

The output for ps -ef | grep Database:

andrea@aavs:~$ ps -ef | grep Database
andrea 6779 6763 0 16:12 pts/2 00:00:00 grep –color=auto Database


TANGO_HOST info:

TANGO_HOST: aavs:10000

Device: sys/database/2
type_id: IDL:Tango/Device_4:1.0
iiop_version: 1.2
host: 10.0.2.15 (10.0.2.15)
port: 10000
Server: DataBaseds/2
Server PID: 1278
Exported: true
last_exported: 2nd March 2016 at 14:49:01
last_unexported: ?

Stored Procedure: release 1.8

Tango Database info:

TANGO Database sys/database/2

Running since 2016-03-02 14:49:01

Devices defined = 10
Devices exported = 5
Device servers defined = 5
Device servers exported = 3

Device properties defined = 14 [History lgth = 18]
Class properties defined = 62 [History lgth = 14]
Device attribute properties defined = 0 [History lgth = 0]
Class attribute properties defined = 0 [History lgth = 0]
Object properties defined = 0 [History lgth = 0]

If I go to ITANGO, and get a proxy to the database device with:
mydev = Device("sys/database/2"), this takes quite a long time.

A ping:
ITango [3]: mydev.ping()
Result [3]: 107

I am not explicitly starting the database server - this runs automatically on system startup in Ubuntu as far as I know.

Thanks for your help,
Andrea
Dr Andrea DeMarco, BSc (Hons) (Melita), MSc (Melita), DPhil (UEA)
Lecturer | Researcher
Department of Physics
Institute of Space Sciences and Astronomy

Room 220, Maths and Physics Building
University of Malta, Msida MSD2080, MALTA
rbourtembourg avatar
Reynald
Hi Andrea,

It might be that your host aavs is not well recognized by your DNS system.
If you are not using DNS, could you please check your /etc/hosts file and be sure that aavs hostname is well defined with the correct IP address there.

I find strange the following line shown by jive:
host: 10.0.2.15 (10.0.2.15)

It should be:
host: aavs (10.0.2.15)

Since your TANGO_HOST is defined as aavs:10000, there might be an issue in your network configuration and this might be the cause of your problems…

Did you change anything recently related to your network configuration?

Hoping this helps,
Reynald
Rosenberg's Law: Software is easy to make, except when you want it to do something new.
Corollary: The only software that's worth making is software that does something new.
rbourtembourg avatar
Reynald
Hi,

Are you sure there is no other host configured with the same IP address on your network?
This could cause this kind of strange behaviours too…

Cheers,
Reynald
Rosenberg's Law: Software is easy to make, except when you want it to do something new.
Corollary: The only software that's worth making is software that does something new.
ademarco avatar
drea
Hi Reynald, thanks for your input.

My hostnames seem to be well defined:

127.0.0.1 localhost
127.0.1.1 aavs

If I do an ifconfig:
andrea@aavs:~$ ifconfig
eth0 Link encap:Ethernet HWaddr 08:00:27:d9:9e:6b
inet addr:10.0.2.15 Bcast:10.0.2.255 Mask:255.255.255.0
inet6 addr: fe80::a00:27ff:fed9:9e6b/64 Scope:Link
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:17654 errors:0 dropped:0 overruns:0 frame:0
TX packets:8056 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:15043239 (15.0 MB) TX bytes:513229 (513.2 KB)

lo Link encap:Local Loopback
inet addr:127.0.0.1 Mask:255.0.0.0
inet6 addr: ::1/128 Scope:Host
UP LOOPBACK RUNNING MTU:65536 Metric:1
RX packets:3035 errors:0 dropped:0 overruns:0 frame:0
TX packets:3035 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:0
RX bytes:610130 (610.1 KB) TX bytes:610130 (610.1 KB)

This is quite a simple setup, and no other machines on the network have the same IP address…


EDIT:
I seem to not have a TANGO_HOST environment variable set up:
andrea@aavs:~$ echo $TANGO_HOST

andrea@aavs:~$

I have set this to aavs:10000 now, but still no effect :(

Cheers,
Andrea
Dr Andrea DeMarco, BSc (Hons) (Melita), MSc (Melita), DPhil (UEA)
Lecturer | Researcher
Department of Physics
Institute of Space Sciences and Astronomy

Room 220, Maths and Physics Building
University of Malta, Msida MSD2080, MALTA
Edited 8 years ago
 
Register or login to create to post a reply.