↓ Skip to main content
blog o’thnet

Solaris 11 Express: Problem #4

·1423 words·7 mins·
IPS Bug
Julien Gabel
Author
Julien Gabel
Multi-platform UNIX systems administrator and consultant in mutualized and virtualized environments.

install/distribution-constructor 0.5.11-0.151.0.1 installed —–

pkg search constructor
#

pkg: Some repositories failed to respond appropriately: solaris: http protocol error: code: 503 reason: Service Unavailable URL: ‘http://unic.thilelli.net/solaris/search/1/False_2_None_None_%3A%3A%3Aconstructor'

Ouch, the newly created repository is unsearchable... And in fact there is no index directory provided in the /dpool/store/data/repo_support/repo/publisher/solaris sub-directory. So, in order to create one we need to force a refresh of the repository.

# svccfg -s pkg/server setprop pkg/readonly=false
# svcadm refresh pkg/server
# pkgrepo refresh -s http://unic.thilelli.net/
Repository refresh initiated.

But just after initiating the refresh of the repository, I started seeing a very high load on the disk on which the dpool is built, and which hosts now the local repository.

# iostat -xnz 2
[...]
                    extended device statistics              
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device
   92.0    0.0  195.0    0.0  3.1  1.0   33.3   10.8  89 100 c9t1d0

So, what is causing this huge I/O workload? Fire iosnoop, and iotop from the DTraceToolkit to observe the activity, and find who is doing these I/O:

# /opt/DTT/Bin/iosnoop
^C
    0   747 R 261342101   3072 pkg.depotd 
    0   747 R 266583819   3072 pkg.depotd 
    0   747 R 55676891    1536 pkg.depotd 
    0   747 R 260418077   2048 pkg.depotd 


/opt/DTT/Bin/iotop 
    

    
    
        #
            
    



Tracing… Please wait.


2011 Jan 10 19:26:36,  load: 0.58,  disk_r:    910 KB,  disk_w:  12667 KB


UID    PID   PPID CMD              DEVICE  MAJ MIN D            BYTES
0      0      0                  sd3      94 192               5632
0      5      0 zpool-rpool      sd2      94 128 W           215552
0    312      0 zpool-dpool      sd3      94 192 R           401408
0    747      9 pkg.depotd       sd3      94 192 R           530944
0    312      0 zpool-dpool      sd3      94 192 W         12755968

Ok, so it seems that the local repository is the culprit. How is the process and its LWP working at this same time?

# prstat -cZmL -p `pgrep pkg.depotd` 2
Please wait...
[...]
   PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID 
   747 root     0.1 0.6 0.0 0.0 0.0 0.0  99 0.0 118   2 254   0 pkg.depotd/2
   747 root     0.1 0.0 0.0 0.0 0.0 0.0 100 0.0 103   0 103   0 pkg.depotd/3
   747 root     0.0 0.0 0.0 0.0 0.0 0.0 100 0.0  80   1  48   0 pkg.depotd/1
   747 root     0.0 0.0 0.0 0.0 0.0 0.0 100 0.0  10   0   5   0 pkg.depotd/4
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/15
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/14
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/13
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/12
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/11
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/10
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/9
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/8
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/7
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/6
   747 root     0.0 0.0 0.0 0.0 0.0 100 0.0 0.0   0   0   0   0 pkg.depotd/5
ZONEID     NLWP  SWAP   RSS MEMORY      TIME  CPU ZONE                        
     0       64  635M  736M    36%   0:01:22 0.4% global                      
Total: 1 processes, 64 lwps, load averages: 0.29, 0.31, 0.25

Ok, the LWP #2 of the pkg.depotd program seems hot here. What is the content of the running stack trace for this particular LWP?

# pstack 747/2
747:    /usr/bin/python2.6 /usr/lib/pkg.depotd --cfg svc:/application/pkg/serv
-----------------  lwp# 2 / thread# 2  --------------------

In this series, I will report the bugs or problems I find when running
the Oracle Solaris 11 Express distribution. I hope this will give more
visibility on those PR to Oracle to correct them before the release of
Solaris 11 next year.


Here is one way you can use to create a local copy of an Oracle Solaris
11 Express IPS package repository. This is based on the Oracle document
on this exact
purpose,
and the README file provided as part of the ISO media which provides
the entire IPS package repository.


The dpool/store/data is a compressed ZFS dataset. Here, we duplicate
the content of the Oracle Solaris 11 Express IPS package repository from
the ISO media. Then, the pkg/server SMF is enabled.


# mkdir /dpool/store/data/repo_support
# mount -F hsfs `lofiadm -a /dpool/store/iso/sol-11-exp-201011-repo-full.iso` /mnt
# rsync -aP /mnt/repo /dpool/store/data/repo_support
# umount /mnt
# lofiadm -d /dev/lofi/1
# svccfg -s pkg/server setprop pkg/inst_root=/dpool/store/data/repo_support/repo
# svcadm refresh pkg/server
# svcadm enable pkg/server

Last, simply reset the origin for the solaris publisher URI, and verify
the new configuration:
# pkg set-publisher -G http://pkg.oracle.com/solaris/release -g http://unic.thilelli.net/ solaris
# pkg publisher
PUBLISHER                             TYPE     STATUS   URI
solaris                  (preferred)  origin   online   http://unic.thilelli.net/

Then, try some listing and searching with the new local repository:
# pkg list -a | grep constructor
[...]
   [ /usr/lib/python2.6/vendor-packages/pkg/indexer.py:692 (_generic_update_index) ]
 fed57e48 PyEval_EvalCodeEx (87c0530, 87bb8ac, 0, 8bc2d7c, 4, 8bc2d8c) + 91c
 fed594f6 fast_function (87e5df4, fcf1de3c, 4, 4, 0, fef70000) + 176
 fed58fea call_function (fcf1de3c, 3, 629a7d59, fed5337e) + ee
 fed56399 PyEval_EvalFrameEx (8bc2c34, 0, 87bb8ac, 0) + 3029
   [ /usr/lib/python2.6/vendor-packages/pkg/indexer.py:790 (server_update_index) ]
 fed57e48 PyEval_EvalCodeEx (87c05c0, 87bb8ac, 0, 8bc2bfc, 2, 8bc2c04) + 91c
 fed594f6 fast_function (87e5e64, fcf1e00c, 2, 2, 0, fedcc7f4) + 176
 fed58fea call_function (fcf1e00c, 1, 88e7a3ae, fed5337e) + ee
 fed56399 PyEval_EvalFrameEx (8bc2ab4, 0, 880a604, 0) + 3029
   [ /usr/lib/python2.6/vendor-packages/pkg/server/repository.py:1003 (__update_searchdb_unlocked) ]
 fed59488 fast_function (8898a04, fcf1e14c, 2, 2, 0, fedcc7f4) + 108
 fed58fea call_function (fcf1e14c, 1, 88e7a3ae, fed5337e) + ee
 fed56399 PyEval_EvalFrameEx (875ca24, 0, 880a604, 0) + 3029
   [ /usr/lib/python2.6/vendor-packages/pkg/server/repository.py:1431 (__run_update_index) ]
 fed59488 fast_function (8898ed4, fcf1e28c, 1, 1, 0, fedcc7f4) + 108
 fed58fea call_function (fcf1e28c, 0, 88e7a3ae, fed5337e) + ee
 fed56399 PyEval_EvalFrameEx (8a58904, 0, 880a604, 0) + 3029
   [ /usr/lib/python2.6/vendor-packages/pkg/server/repository.py:687 (__refresh_index) ]
 fed59488 fast_function (889880c, fcf1e3cc, 1, 1, 0, fedcc7f4) + 108
 fed58fea call_function (fcf1e3cc, 0, 55, 0) + ee
 fed56399 PyEval_EvalFrameEx (8a5876c, 0, 880a604, 0) + 3029
[...]

It is now pretty clear that refreshing the repository is at the heart of
the the load. When updating the index went well, it will last for five
to ten minutes, and the log will look like this:
# tail -f /var/svc/log/application-pkg-server:default.log
  [04/Nov/2008:09:46:45] ENGINE Listening for SIGTERM.
  [04/Nov/2008:09:46:45] ENGINE Listening for SIGUSR1.
  [04/Nov/2008:09:46:45] ENGINE Bus STARTING
  [04/Nov/2008:09:46:45] ENGINE Started monitor thread '_TimeoutMonitor'.
  [04/Nov/2008:09:46:46] ENGINE Serving on 0.0.0.0:80
  [04/Nov/2008:09:46:46] ENGINE Bus STARTED
  [04/Nov/2008:09:46:51] INDEX Search Available
  [04/Nov/2008:09:46:56] INDEX Updating search indexes
  [04/Nov/2008:09:50:15] INDEX Search indexes updated and available.

The question is why is it so hot, and especially so long with this
repository? The update generate more than 1.5 billion of files under the
index/TMP directory before dying, and trying again... indefinitely:
# tail -f /var/svc/log/application-pkg-server:default.log
[...]
[ Jan 12 04:16:10 Stopping because all processes in service exited. ]
[ Jan 12 04:16:18 Executing start method ("//lib/svc/method/svc-pkg-depot start"). ]
Dropping net_privaddr privilege.
ppriv -s A=basic,-file_link_any,-proc_info,-proc_session,net_privaddr -e /usr/lib/pkg.depotd --cfg svc:/application/pkg/server:default
[12/Jan/2011:04:16:26] ENGINE Listening for SIGHUP.
[12/Jan/2011:04:16:26] ENGINE Listening for SIGTERM.
[12/Jan/2011:04:16:26] ENGINE Listening for SIGUSR1.
[12/Jan/2011:04:16:26] ENGINE Bus STARTING
[12/Jan/2011:04:16:26] INDEX Checking for updated package data.
[12/Jan/2011:04:16:26] ENGINE Started monitor thread '_TimeoutMonitor'.
[12/Jan/2011:04:16:27] ENGINE Serving on 0.0.0.0:80
[12/Jan/2011:04:16:27] ENGINE Bus STARTED
[12/Jan/2011:04:16:27] INDEX Updating search indexes
[ Jan 12 07:36:09 Stopping because all processes in service exited. ]
[ Jan 12 07:36:17 Executing start method ("//lib/svc/method/svc-pkg-depot start"). ]
Dropping net_privaddr privilege.
ppriv -s A=basic,-file_link_any,-proc_info,-proc_session,net_privaddr -e /usr/lib/pkg.depotd --cfg svc:/application/pkg/server:default
[12/Jan/2011:07:36:28] ENGINE Listening for SIGHUP.
[12/Jan/2011:07:36:28] ENGINE Listening for SIGTERM.
[12/Jan/2011:07:36:28] ENGINE Listening for SIGUSR1.
[12/Jan/2011:07:36:28] ENGINE Bus STARTING
[12/Jan/2011:07:36:28] INDEX Checking for updated package data.
[12/Jan/2011:07:36:28] ENGINE Started monitor thread '_TimeoutMonitor'.
[12/Jan/2011:07:36:28] ENGINE Serving on 0.0.0.0:80
[12/Jan/2011:07:36:28] ENGINE Bus STARTED
[12/Jan/2011:07:36:29] INDEX Updating search indexes

So, I am asking me why the index is not provided as part of the ISO
media... Nonetheless, the problem is that I can't now enable the
pkg/server SMF service anymore without pkg.depotd trying to update
the index... Too bad. So, I decided to reinstall the depot from the
beginning, but how can I create an index properly with this release from
the ISO media?
Update #1 (2011-01-19): Well, I think I find a better way (the proper
way?) to achieve this without problem: use the file path as an argument
to the pkgrepo command.
# svccfg -s pkg/server setprop pkg/readonly=true
# svcadm refresh pkg/server
# svcadm restart pkg/server
# pkgrepo -s /dpool/store/data/repo_support/repo refresh
Repository refresh initiated.
# tail /var/svc/log/application-pkg-server\:default.log 
[...]
[17/Jan/2011:21:51:37]  pkg://solaris/SUNWdcopy@0.5.11,5.11-0.133:20101027T183617Z
[17/Jan/2011:21:51:37]  pkg://solaris/driver/x11/xsvc@0.5.11,5.11-0.151.0.1:20101104T233133Z
[17/Jan/2011:21:51:37]  pkg://solaris/SUNWdedis@0.5.11,5.11-0.130:20101027T183621Z
[17/Jan/2011:21:51:40] INDEX Checking for updated package data.
# pkg search -s http://unic.thilelli.net/ constructor
INDEX           ACTION VALUE                                                       PACKAGE
pkg.description set    Distribution Constructor libraries, commands and data files pkg:/install/distribution-constructor@0.5.11-0.151.0.1