"apt-get update" runs for 20 minutes...

Hi All,

First post, I've been stuck on a problem got 2 weeks now. When I run apt-get update on my Ubuntu 12.10 machine it hangs for 20 minutes on 'Reading Package Lists...##%' which on my Debian 6 server takes less than a second. My machine is quite powerful and I've been able to do most everything else; install steam, run TF2, music, videos, xbmc and so on... so I know it's working. I can't see any errors in logs that could explain this. So far my best lead is the ltrace and strace I ran to see where the time was being spent but I don't know how to diagnose further.

Any and all help appreciated!

strace -c apt-get update:

Code:

---

% time    seconds  usecs/call    calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 93.25    0.005222        373        14          waitpid
  4.54    0.000254          0      2662          read
  1.61    0.000090          0      875      286 stat64
  0.61    0.000034          1        30          munmap
  0.00    0.000000          0      590          write
  0.00    0.000000          0      240        6 open
  0.00    0.000000          0      309          close
  0.00    0.000000          0        10        9 unlink
  0.00    0.000000          0        1          execve
  0.00    0.000000          0        4          chdir
  0.00    0.000000          0        17          chmod
  0.00    0.000000          0        1          getpid
  0.00    0.000000          0        12        11 access
  0.00    0.000000          0        10          kill
  0.00    0.000000          0        35          rename
  0.00    0.000000          0        21          dup
  0.00    0.000000          0        23          pipe
  0.00    0.000000          0        11          brk
  0.00    0.000000          0        2          ioctl
  0.00    0.000000          0      232          gettimeofday
  0.00    0.000000          0        2          fchmod
  0.00    0.000000          0        2          fsync
  0.00    0.000000          0        14          clone
  0.00    0.000000          0        14          mprotect
  0.00    0.000000          0        27        3 _llseek
  0.00    0.000000          0      452          select
  0.00    0.000000          0        4          msync
  0.00    0.000000          0        4          rt_sigaction
  0.00    0.000000          0      254          rt_sigprocmask
  0.00    0.000000          0        2          getcwd
  0.00    0.000000          0        62          mmap2
  0.00    0.000000          0        1          ftruncate64
  0.00    0.000000          0        2        2 lstat64
  0.00    0.000000          0      262          fstat64
  0.00    0.000000          0        1          getuid32
  0.00    0.000000          0        16          getdents64
  0.00    0.000000          0      305          fcntl64
  0.00    0.000000          0        1          set_thread_area
  0.00    0.000000          0        8          openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.005600                  6532      317 total

---

ltrace -c apt-get update:

Code:

---

% time    seconds  usecs/call    calls      function
------ ----------- ----------- --------- --------------------
 49.93  991.580396  991580396        1 _ZN11CommandLine11DispatchArgEPNS_8DispatchEb
 44.92  892.111896  892111896        1 _ZN12pkgCacheFile11BuildCachesEP10OpProgressb
  5.01  99.452689    99452689        1 _Z10ListUpdateR16pkgAcquireStatusR13pkgSourceListi
  0.10    2.011690        4460      451 sigaddset
  0.01    0.174376          28      6147 strlen
  0.00    0.095587          26      3542 _ZN10pkgAcquire10WorkerStepEPNS_6WorkerE
  0.00    0.062476          31      1980 _ZSt16__ostream_insertIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_PKS3_i
  0.00    0.058722        130      451 _ZN16pkgAcquireStatus5PulseEP10pkgAcquire
  0.00    0.051496          28      1797 __snprintf_chk
  0.00    0.041437          45      902 sigprocmask
  0.00    0.035268          63      559 _ZNSo5flushEv
  0.00    0.027825          26      1041 _ZNSs4_Rep10_M_destroyERKSaIcE
  0.00    0.027084          31      858 _Z9SizeToStrd
  0.00    0.025476          40      631 memset
  0.00    0.025083          39      631 __sprintf_chk
  0.00    0.013495          28      481 snprintf
  0.00    0.012177      12177        1 _ZN12pkgCacheFile12RemoveCachesEv
  0.00    0.011808          26      451 sigemptyset
  0.00    0.008400          78      107 _ZNSo3putEc
  0.00    0.008065          50      159 gettext
  0.00    0.006206          34      181 _Z9TimeToStrm
  0.00    0.005443          70        77 _ZN16pkgAcquireStatus7FetchedEyy
  0.00    0.004580          25      180 memcpy
  0.00    0.004548          25      180 __udivdi3
  0.00    0.002492        1246        2 _ZN12pkgCacheFile15BuildSourceListEP10OpProgress
  0.00    0.002120        2120        1 _Z13pkgInitConfigR13Configuration
  0.00    0.001686          29        57 _ZNSt8ios_base4InitD1Ev
  0.00    0.001618          26        60 _ZNSo9_M_insertImEERSoT_
  0.00    0.000255        255        1 _ZN16pkgAcquireStatus4StopEv
  0.00    0.000219        219        1 _ZN12pkgCacheFileD2Ev
  0.00    0.000163        163        1 _Z13pkgInitSystemR13ConfigurationRP9pkgSystem
  0.00    0.000132          66        2 signal
  0.00    0.000131          26        5 _ZNK13Configuration5FindBEPKcRKb
  0.00    0.000122          40        3 _Z12_GetErrorObjv
  0.00    0.000109          27        4 _ZNK13Configuration5FindIEPKcRKi
  0.00    0.000106        106        1 setlocale
  0.00    0.000094          94        1 _ZNSt14basic_ofstreamIcSt11char_traitsIcEED1Ev
  0.00    0.000092          30        3 _ZNSoD1Ev
  0.00    0.000089          14        6 __cxa_atexit
  0.00    0.000088          29        3 _ZNSt9basic_iosIcSt11char_traitsIcEE5rdbufEPSt15basic_streambufIcS1_E
  0.00    0.000087          87        1 _Z8ioprintfRSoPKcz
  0.00    0.000068          34        2 _ZNK11CommandLine8FileSizeEv
  0.00    0.000065          65        1 _ZN14OpTextProgress4DoneEv
  0.00    0.000062          62        1 getuid
  0.00    0.000060          60        1 isatty
  0.00    0.000058          58        1 ioctl
  0.00    0.000049          49        1 _ZNSt14basic_ofstreamIcSt11char_traitsIcEEC1EPKcSt13_Ios_Openmode
  0.00    0.000048          16        3 _ZNSoC1EPSt15basic_streambufIcSt11char_traitsIcEE
  0.00    0.000041          41        1 _ZN12pkgCacheFileC2Ev
  0.00    0.000040          40        1 _ZN16pkgAcquireStatusC2Ev
  0.00    0.000038          38        1 _ZN14OpTextProgressC1ER13Configuration
  0.00    0.000036          36        1 _ZN16pkgAcquireStatus5StartEv
  0.00    0.000032          32        1 _ZN11CommandLineD1Ev
  0.00    0.000032          32        1 _ZN11GlobalError10DumpErrorsERSoRKNS_7MsgTypeERKb
  0.00    0.000029          14        2 _ZNSt8ios_base4InitC1Ev
  0.00    0.000019          19        1 _ZN11CommandLine5ParseEiPPKc
  0.00    0.000016          16        1 textdomain
  0.00    0.000016          16        1 _ZN11CommandLineC1EPNS_4ArgsEP13Configuration
------ ----------- ----------- --------- --------------------
100.00 1985.866535                20983 total

---

Link to my previous investigations: ubuntuforums.org - Installation & Upgrades - "6 Hour+ install time, apt-get / dpkg broken!?"

(can't post links yet)

Thanks,
Noki

The only time I've seen 'apt-get update' run slow is when DNS is down.

During the execution of 'apt-get update', are you seeing any timeout error messages in the output? If so, then this is definitely a DNS related issue! Can you paste the output of the command on pastebin?

Cheers,
tk.

Hi, I don't think it is DNS as my Debian server can do the same thing without issue. Also I think that it's done getting information from the web by the time it gets to the 'Reading Package Lists...' stage.

I'm sure I could prove this by removing all web sources and adding only the DVD for content, but I'm at work right now.

What is clear from the above output is that '_ZN11CommandLine11DispatchArgEPNS_8DispatchEb' & '_ZN12pkgCacheFile11BuildCachesEP10OpProgressb' are hogging ALL of the time. Making single call each and then taking around 900 seconds to finish. Why on earth could this be?

Thanks,
Noki

my entire apt-get update output

pastebin dot com slash 3ijrv3ji (cant paste links yet)

with the last step where it slows and takes 20+ minutes.

thanks again, any help diagnosing this is appreciated.
Noki

Hi All,

I've just run another apt-get update, this time with ltrace. It shows I've been able to get the time down from 33+minutes in my first post to around 25 minutes, mostly thanks to help in various forums, thanks again!

ltrace -c apt-get update:

pastebin dot com slash eyENvETS

This is the section that most interests me;

Code:

---

% time    seconds  usecs/call    calls      function
------ ----------- ----------- --------- --------------------
 47.44  713.119059  713119059        1 _ZN11CommandLine11DispatchArgEPNS_8DispatchEb
 47.07  707.538760  707538760        1 _ZN12pkgCacheFile11BuildCachesEP10OpProgressb
  1.82  27.321004      53153      514 select
  1.07  16.064317      297487        54 _Z6WaitFdibm
  0.57    8.509646      607831        14 curl_easy_perform
  0.50    7.568873    7568873        1 _Z10ListUpdateR16pkgAcquireStatusR13pkgSourceListi
  0.39    5.889650        7464      789 _ZN6FileFd5WriteEPKvy
  0.18    2.730817          65    41782 __umoddi3
  0.17    2.564672        8116      316 write
  0.14    2.047325        2252      909 _ZSt16__ostream_insertIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_PKS3_i
  0.14    2.041083        755      2700 isspace
  0.13    2.022598        1335      1514 _ZNSs12_M_leak_hardEv
  0.13    2.017244        2266      890 _ZN10pkgAcquire10WorkerStepEPNS_6WorkerE
  0.05    0.718136        188      3818 _IO_getc
  0.02    0.334594        1262      265 _ZN12pkgAcqMethod3RunEb

---

Also, I've just found a new error, my machine keeps needing to send error reports to Ubuntu which has only started in the last 2 days. It seems to happen when I use the Software centre to install things. Specifically it complains about aptd. I looked at the manpage and found a debug command which outputs:

aptd -d

Code:

---

noki@TALLBOY:~$ aptd -d
12:31:09 AptDaemon [INFO]: Initializing daemon
Traceback (most recent call last):
  File "/usr/sbin/aptd", line 37, in <module>
    aptdaemon.core.main()
  File "/usr/lib/python3/dist-packages/aptdaemon/core.py", line 2233, in main
    daemon = AptDaemon(options, bus=bus)
  File "/usr/lib/python3/dist-packages/aptdaemon/core.py", line 1414, in __init__
    do_not_queue=True)
  File "/usr/lib/python3/dist-packages/dbus/service.py", line 131, in __new__
    retval = bus.request_name(name, name_flags)
  File "/usr/lib/python3/dist-packages/dbus/bus.py", line 303, in request_name
    'su', (name, flags))
  File "/usr/lib/python3/dist-packages/dbus/connection.py", line 651, in call_blocking
    message, timeout)
dbus.exceptions.DBusException: org.freedesktop.DBus.Error.AccessDenied: Connection ":1.76" is not allowed to own the service "org.debian.apt" due to security policies in the configuration file

---

Thanks,
Noki